From b8ef62e5024c653bf04414bb3b5fb4577d896b59 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jes=C3=BAs=20Espino?= Date: Mon, 16 Dec 2019 13:57:21 +0100 Subject: [PATCH] Adding structuredLogging check and fix inconsistencies (#13370) * Adding structuredLogging check and fix inconsistencies * Addressing PR review comments * Addressing PR review comments * Addressing PR review comments * Addressing PR review comments * Addressing PR review comments --- Makefile | 2 +- api4/system_test.go | 3 ++- app/command.go | 3 +-- app/email_batching.go | 4 ++-- app/file.go | 3 ++- app/ldap.go | 3 +-- app/server.go | 19 ++++++++++++++++--- i18n/en.json | 4 ---- store/sqlstore/post_store.go | 2 +- wsapi/websocket_handler.go | 21 +++++++++++++++++---- 10 files changed, 43 insertions(+), 21 deletions(-) diff --git a/Makefile b/Makefile index 62a4df5c0f..64611621fe 100644 --- a/Makefile +++ b/Makefile @@ -454,7 +454,7 @@ vet: ## Run mattermost go vet specific checks exit 1; \ fi; \ - $(GO) vet -vettool=$(GOPATH)/bin/mattermost-govet -license ./... + $(GO) vet -vettool=$(GOPATH)/bin/mattermost-govet -license -structuredLogging ./... ifeq ($(BUILD_ENTERPRISE_READY),true) $(GO) vet -vettool=$(GOPATH)/bin/mattermost-govet -enterpriseLicense ./enterprise/... endif diff --git a/api4/system_test.go b/api4/system_test.go index 539ba78287..a38d815fcb 100644 --- a/api4/system_test.go +++ b/api4/system_test.go @@ -8,6 +8,7 @@ import ( "net/http" "net/http/httptest" "os" + "strconv" "strings" "testing" "time" @@ -242,7 +243,7 @@ func TestGetLogs(t *testing.T) { Client := th.Client for i := 0; i < 20; i++ { - mlog.Info(fmt.Sprint(i)) + mlog.Info(strconv.Itoa(i)) } logs, resp := th.SystemAdminClient.GetLogs(0, 10) diff --git a/app/command.go b/app/command.go index eba75cb1df..01d847021a 100644 --- a/app/command.go +++ b/app/command.go @@ -4,7 +4,6 @@ package app import ( - "fmt" "io" "io/ioutil" "net/http" @@ -272,7 +271,7 @@ func (a *App) tryExecuteCustomCommand(args *model.CommandArgs, trigger string, m return nil, nil, nil } - mlog.Debug(fmt.Sprintf(utils.T("api.command.execute_command.debug"), trigger, args.UserId)) + mlog.Debug("Executing command", mlog.String("command", trigger), mlog.String("user_id", args.UserId)) p := url.Values{} p.Set("token", cmd.Token) diff --git a/app/email_batching.go b/app/email_batching.go index 664a40f96d..839df1e3dc 100644 --- a/app/email_batching.go +++ b/app/email_batching.go @@ -71,7 +71,7 @@ func NewEmailBatchingJob(s *Server, bufferSize int) *EmailBatchingJob { } func (job *EmailBatchingJob) Start() { - mlog.Debug(fmt.Sprintf("Email batching job starting. Checking for pending emails every %v seconds.", *job.server.Config().EmailSettings.EmailBatchingInterval)) + mlog.Debug("Email batching job starting. Checking for pending emails periodically.", mlog.Int("interval_in_seconds", *job.server.Config().EmailSettings.EmailBatchingInterval)) newTask := model.CreateRecurringTask(EMAIL_BATCHING_TASK_NAME, job.CheckPendingEmails, time.Duration(*job.server.Config().EmailSettings.EmailBatchingInterval)*time.Second) job.taskMutex.Lock() @@ -107,7 +107,7 @@ func (job *EmailBatchingJob) CheckPendingEmails() { // without actually sending emails job.checkPendingNotifications(time.Now(), job.server.sendBatchedEmailNotification) - mlog.Debug(fmt.Sprintf("Email batching job ran. %v user(s) still have notifications pending.", len(job.pendingNotifications))) + mlog.Debug("Email batching job ran. Some users still have notifications pending.", mlog.Int("number_of_users", len(job.pendingNotifications))) } func (job *EmailBatchingJob) handleNewNotifications() { diff --git a/app/file.go b/app/file.go index 0b934e13d7..3dc20d4f37 100644 --- a/app/file.go +++ b/app/file.go @@ -145,10 +145,11 @@ func (a *App) getInfoForFilename(post *model.Post, teamId, channelId, userId, ol data, err := a.ReadFile(path) if err != nil { mlog.Error( - fmt.Sprintf("File not found when migrating post to use FileInfos, err=%v", err), + "File not found when migrating post to use FileInfos", mlog.String("post_id", post.Id), mlog.String("filename", filename), mlog.String("path", path), + mlog.Err(err), ) return nil } diff --git a/app/ldap.go b/app/ldap.go index b040d2127e..6579190929 100644 --- a/app/ldap.go +++ b/app/ldap.go @@ -4,7 +4,6 @@ package app import ( - "fmt" "net/http" "github.com/mattermost/mattermost-server/v5/mlog" @@ -19,7 +18,7 @@ func (a *App) SyncLdap() { if ldapI := a.Ldap; ldapI != nil { ldapI.StartSynchronizeJob(false) } else { - mlog.Error(fmt.Sprintf("%v", model.NewAppError("SyncLdap", "ent.ldap.disabled.app_error", nil, "", http.StatusNotImplemented).Error())) + mlog.Error("Not executing ldap sync because ldap is not available") } } }) diff --git a/app/server.go b/app/server.go index 5fe54e217f..815ce27830 100644 --- a/app/server.go +++ b/app/server.go @@ -215,8 +215,20 @@ func NewServer(options ...Option) (*Server, error) { } }) - mlog.Info(fmt.Sprintf("Current version is %v (%v/%v/%v/%v)", model.CurrentVersion, model.BuildNumber, model.BuildDate, model.BuildHash, model.BuildHashEnterprise)) - mlog.Info(fmt.Sprintf("Enterprise Enabled: %v", model.BuildEnterpriseReady)) + logCurrentVersion := fmt.Sprintf("Current version is %v (%v/%v/%v/%v)", model.CurrentVersion, model.BuildNumber, model.BuildDate, model.BuildHash, model.BuildHashEnterprise) + mlog.Info( + logCurrentVersion, + mlog.String("current_version", model.CurrentVersion), + mlog.String("build_number", model.BuildNumber), + mlog.String("build_date", model.BuildDate), + mlog.String("build_hash", model.BuildHash), + mlog.String("build_hash_enterprise", model.BuildHashEnterprise), + ) + if model.BuildEnterpriseReady == "true" { + mlog.Info("Enterprise Build", mlog.Bool("enterprise_build", true)) + } else { + mlog.Info("Team Edition Build", mlog.Bool("enterprise_build", false)) + } pwd, _ := os.Getwd() mlog.Info("Printing current working", mlog.String("directory", pwd)) @@ -505,7 +517,8 @@ func (s *Server) Start() error { } s.ListenAddr = listener.Addr().(*net.TCPAddr) - mlog.Info(fmt.Sprintf("Server is listening on %v", listener.Addr().String())) + logListeningPort := fmt.Sprintf("Server is listening on %v", listener.Addr().String()) + mlog.Info(logListeningPort, mlog.String("address", listener.Addr().String())) // Migration from old let's encrypt library if *s.Config().ServiceSettings.UseLetsEncrypt { diff --git a/i18n/en.json b/i18n/en.json index 8871ff6316..96398dee4c 100644 --- a/i18n/en.json +++ b/i18n/en.json @@ -431,10 +431,6 @@ "id": "api.command.execute_command.create_post_failed.app_error", "translation": "Command '{{.Trigger}}' failed to post response. Please contact your System Administrator." }, - { - "id": "api.command.execute_command.debug", - "translation": "Executing cmd=%v userId=%v" - }, { "id": "api.command.execute_command.failed.app_error", "translation": "Command with a trigger of '{{.Trigger}}' failed" diff --git a/store/sqlstore/post_store.go b/store/sqlstore/post_store.go index 9362ede90b..9e563e137a 100644 --- a/store/sqlstore/post_store.go +++ b/store/sqlstore/post_store.go @@ -107,7 +107,7 @@ func (s *SqlPostStore) Save(post *model.Post) (*model.Post, *model.AppError) { } } else { if count, err := s.GetMaster().SelectInt("SELECT COUNT(*) FROM Posts WHERE RootId = :Id", map[string]interface{}{"Id": post.Id}); err != nil { - mlog.Error(fmt.Sprintf("Error fetching post's thread: %v", err.Error())) + mlog.Error("Error fetching post's thread.", mlog.Err(err)) } else { post.ReplyCount = count } diff --git a/wsapi/websocket_handler.go b/wsapi/websocket_handler.go index 3812c2c755..b0da94844a 100644 --- a/wsapi/websocket_handler.go +++ b/wsapi/websocket_handler.go @@ -4,7 +4,6 @@ package wsapi import ( - "fmt" "net/http" "github.com/mattermost/mattermost-server/v5/app" @@ -23,11 +22,18 @@ type webSocketHandler struct { } func (wh webSocketHandler) ServeWebSocket(conn *app.WebConn, r *model.WebSocketRequest) { - mlog.Debug(fmt.Sprintf("websocket: %s", r.Action)) + mlog.Debug("Websocket request", mlog.String("action", r.Action)) session, sessionErr := wh.app.GetSession(conn.GetSessionToken()) if sessionErr != nil { - mlog.Error(fmt.Sprintf("%v:%v seq=%v uid=%v %v [details: %v]", "websocket", r.Action, r.Seq, conn.UserId, sessionErr.SystemMessage(utils.T), sessionErr.Error())) + mlog.Error( + "websocket session error", + mlog.String("action", r.Action), + mlog.Int64("seq", r.Seq), + mlog.String("user_id", conn.UserId), + mlog.String("error_message", sessionErr.SystemMessage(utils.T)), + mlog.Err(sessionErr), + ) sessionErr.DetailedError = "" errResp := model.NewWebSocketError(r.Seq, sessionErr) @@ -43,7 +49,14 @@ func (wh webSocketHandler) ServeWebSocket(conn *app.WebConn, r *model.WebSocketR var err *model.AppError if data, err = wh.handlerFunc(r); err != nil { - mlog.Error(fmt.Sprintf("%v:%v seq=%v uid=%v %v [details: %v]", "websocket", r.Action, r.Seq, r.Session.UserId, err.SystemMessage(utils.T), err.DetailedError)) + mlog.Error( + "websocket request handling error", + mlog.String("action", r.Action), + mlog.Int64("seq", r.Seq), + mlog.String("user_id", conn.UserId), + mlog.String("error_message", err.SystemMessage(utils.T)), + mlog.Err(err), + ) err.DetailedError = "" errResp := model.NewWebSocketError(r.Seq, err)