From 686c2fbab7607d42183ae685a27ea3d7dce8c3f6 Mon Sep 17 00:00:00 2001 From: Christopher Speller Date: Fri, 27 Apr 2018 12:49:45 -0700 Subject: Structured logging (#8673) * Implementing structured logging * Changes to en.json to allow refactor to run. * Fixing global logger * Structured logger initalization. * Add caller. * Do some log redirection. * Auto refactor * Cleaning up l4g reference and removing dependancy. * Removing junk. * Copyright headers. * Fixing tests * Revert "Changes to en.json to allow refactor to run." This reverts commit fd8249e99bcad0231e6ea65cd77c32aae9a54026. * Fixing some auto refactor strangeness and typo. * Making keys more human readable. --- jobs/jobs.go | 7 ++++--- jobs/jobs_watcher.go | 13 +++++++------ jobs/schedulers.go | 26 +++++++++++++------------- jobs/workers.go | 6 +++--- 4 files changed, 27 insertions(+), 25 deletions(-) (limited to 'jobs') diff --git a/jobs/jobs.go b/jobs/jobs.go index b367730b5..850491403 100644 --- a/jobs/jobs.go +++ b/jobs/jobs.go @@ -5,11 +5,12 @@ package jobs import ( "context" + "fmt" "time" "net/http" - l4g "github.com/alecthomas/log4go" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -125,10 +126,10 @@ func (srv *JobServer) CancellationWatcher(ctx context.Context, jobId string, can for { select { case <-ctx.Done(): - l4g.Debug("CancellationWatcher for Job: %v Aborting as job has finished.", jobId) + mlog.Debug(fmt.Sprintf("CancellationWatcher for Job: %v Aborting as job has finished.", jobId)) return case <-time.After(CANCEL_WATCHER_POLLING_INTERVAL * time.Millisecond): - l4g.Debug("CancellationWatcher for Job: %v polling.", jobId) + mlog.Debug(fmt.Sprintf("CancellationWatcher for Job: %v polling.", jobId)) if result := <-srv.Store.Job().Get(jobId); result.Err == nil { jobStatus := result.Data.(*model.Job) if jobStatus.Status == model.JOB_STATUS_CANCEL_REQUESTED { diff --git a/jobs/jobs_watcher.go b/jobs/jobs_watcher.go index 645715db4..07979442d 100644 --- a/jobs/jobs_watcher.go +++ b/jobs/jobs_watcher.go @@ -4,10 +4,11 @@ package jobs import ( + "fmt" "math/rand" "time" - l4g "github.com/alecthomas/log4go" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -35,7 +36,7 @@ func (srv *JobServer) MakeWatcher(workers *Workers, pollingInterval int) *Watche } func (watcher *Watcher) Start() { - l4g.Debug("Watcher Started") + mlog.Debug("Watcher Started") // Delay for some random number of milliseconds before starting to ensure that multiple // instances of the jobserver don't poll at a time too close to each other. @@ -43,14 +44,14 @@ func (watcher *Watcher) Start() { <-time.After(time.Duration(rand.Intn(watcher.pollingInterval)) * time.Millisecond) defer func() { - l4g.Debug("Watcher Finished") + mlog.Debug("Watcher Finished") watcher.stopped <- true }() for { select { case <-watcher.stop: - l4g.Debug("Watcher: Received stop signal") + mlog.Debug("Watcher: Received stop signal") return case <-time.After(time.Duration(watcher.pollingInterval) * time.Millisecond): watcher.PollAndNotify() @@ -59,14 +60,14 @@ func (watcher *Watcher) Start() { } func (watcher *Watcher) Stop() { - l4g.Debug("Watcher Stopping") + mlog.Debug("Watcher Stopping") watcher.stop <- true <-watcher.stopped } func (watcher *Watcher) PollAndNotify() { if result := <-watcher.srv.Store.Job().GetAllByStatus(model.JOB_STATUS_PENDING); result.Err != nil { - l4g.Error("Error occurred getting all pending statuses: %v", result.Err.Error()) + mlog.Error(fmt.Sprintf("Error occurred getting all pending statuses: %v", result.Err.Error())) } else { jobs := result.Data.([]*model.Job) diff --git a/jobs/schedulers.go b/jobs/schedulers.go index 839cbbae8..2823036df 100644 --- a/jobs/schedulers.go +++ b/jobs/schedulers.go @@ -4,11 +4,11 @@ package jobs import ( + "fmt" "sync" "time" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -25,7 +25,7 @@ type Schedulers struct { } func (srv *JobServer) InitSchedulers() *Schedulers { - l4g.Debug("Initialising schedulers.") + mlog.Debug("Initialising schedulers.") schedulers := &Schedulers{ stop: make(chan bool), @@ -59,10 +59,10 @@ func (schedulers *Schedulers) Start() *Schedulers { go func() { schedulers.startOnce.Do(func() { - l4g.Info("Starting schedulers.") + mlog.Info("Starting schedulers.") defer func() { - l4g.Info("Schedulers stopped.") + mlog.Info("Schedulers stopped.") close(schedulers.stopped) }() @@ -78,7 +78,7 @@ func (schedulers *Schedulers) Start() *Schedulers { for { select { case <-schedulers.stop: - l4g.Debug("Schedulers received stop signal.") + mlog.Debug("Schedulers received stop signal.") return case now = <-time.After(1 * time.Minute): cfg := schedulers.jobs.Config() @@ -93,8 +93,8 @@ func (schedulers *Schedulers) Start() *Schedulers { if scheduler != nil { if scheduler.Enabled(cfg) { if _, err := schedulers.scheduleJob(cfg, scheduler); err != nil { - l4g.Warn("Failed to schedule job with scheduler: %v", scheduler.Name()) - l4g.Error(err) + mlog.Warn(fmt.Sprintf("Failed to schedule job with scheduler: %v", scheduler.Name())) + mlog.Error(fmt.Sprint(err)) } else { schedulers.setNextRunTime(cfg, idx, now, true) } @@ -119,7 +119,7 @@ func (schedulers *Schedulers) Start() *Schedulers { } func (schedulers *Schedulers) Stop() *Schedulers { - l4g.Info("Stopping schedulers.") + mlog.Info("Stopping schedulers.") close(schedulers.stop) <-schedulers.stopped return schedulers @@ -130,7 +130,7 @@ func (schedulers *Schedulers) setNextRunTime(cfg *model.Config, idx int, now tim if !pendingJobs { if pj, err := schedulers.jobs.CheckForPendingJobsByType(scheduler.JobType()); err != nil { - l4g.Error("Failed to set next job run time: " + err.Error()) + mlog.Error("Failed to set next job run time: " + err.Error()) schedulers.nextRunTimes[idx] = nil return } else { @@ -140,13 +140,13 @@ func (schedulers *Schedulers) setNextRunTime(cfg *model.Config, idx int, now tim lastSuccessfulJob, err := schedulers.jobs.GetLastSuccessfulJobByType(scheduler.JobType()) if err != nil { - l4g.Error("Failed to set next job run time: " + err.Error()) + mlog.Error("Failed to set next job run time: " + err.Error()) schedulers.nextRunTimes[idx] = nil return } schedulers.nextRunTimes[idx] = scheduler.NextScheduleTime(cfg, now, pendingJobs, lastSuccessfulJob) - l4g.Debug("Next run time for scheduler %v: %v", scheduler.Name(), schedulers.nextRunTimes[idx]) + mlog.Debug(fmt.Sprintf("Next run time for scheduler %v: %v", scheduler.Name(), schedulers.nextRunTimes[idx])) } func (schedulers *Schedulers) scheduleJob(cfg *model.Config, scheduler model.Scheduler) (*model.Job, *model.AppError) { @@ -164,6 +164,6 @@ func (schedulers *Schedulers) scheduleJob(cfg *model.Config, scheduler model.Sch } func (schedulers *Schedulers) handleConfigChange(oldConfig *model.Config, newConfig *model.Config) { - l4g.Debug("Schedulers received config change.") + mlog.Debug("Schedulers received config change.") schedulers.configChanged <- newConfig } diff --git a/jobs/workers.go b/jobs/workers.go index ca34855e5..57a255013 100644 --- a/jobs/workers.go +++ b/jobs/workers.go @@ -6,7 +6,7 @@ package jobs import ( "sync" - l4g "github.com/alecthomas/log4go" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -54,7 +54,7 @@ func (srv *JobServer) InitWorkers() *Workers { } func (workers *Workers) Start() *Workers { - l4g.Info("Starting workers") + mlog.Info("Starting workers") workers.startOnce.Do(func() { if workers.DataRetention != nil && (*workers.ConfigService.Config().DataRetentionSettings.EnableMessageDeletion || *workers.ConfigService.Config().DataRetentionSettings.EnableFileDeletion) { @@ -152,7 +152,7 @@ func (workers *Workers) Stop() *Workers { workers.LdapSync.Stop() } - l4g.Info("Stopped workers") + mlog.Info("Stopped workers") return workers } -- cgit v1.2.3-1-g7c22