Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce log verbosity and add message to logs that didn't have one #3478

Merged
merged 1 commit into from
Aug 26, 2020
Merged

Reduce log verbosity and add message to logs that didn't have one #3478

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion common/service/dynamicconfig/config.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ func (c *Collection) logValue(
) {
loadedValue, loaded := c.keys.LoadOrStore(key, value)
if !loaded || !cmpValueEquals(loadedValue, value) {
c.logger.Info("Get dynamic config",
c.logger.Debug("Get dynamic config",
tag.Name(key.String()), tag.Value(value), tag.DefaultValue(defaultValue))
}
}
Expand Down
10 changes: 5 additions & 5 deletions service/frontend/workflowHandler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2549,7 +2549,7 @@ func (wh *WorkflowHandler) ListOpenWorkflowExecutions(
WorkflowID: listRequest.ExecutionFilter.GetWorkflowId(),
})
}
wh.GetLogger().Info("List open workflow with filter",
wh.GetLogger().Debug("List open workflow with filter",
tag.WorkflowDomainName(listRequest.GetDomain()), tag.WorkflowListWorkflowFilterByID)
} else if listRequest.TypeFilter != nil {
if wh.config.DisableListVisibilityByFilter(domain) {
Expand All @@ -2560,7 +2560,7 @@ func (wh *WorkflowHandler) ListOpenWorkflowExecutions(
WorkflowTypeName: listRequest.TypeFilter.GetName(),
})
}
wh.GetLogger().Info("List open workflow with filter",
wh.GetLogger().Debug("List open workflow with filter",
tag.WorkflowDomainName(listRequest.GetDomain()), tag.WorkflowListWorkflowFilterByType)
} else {
persistenceResp, err = wh.GetVisibilityManager().ListOpenWorkflowExecutions(&baseReq)
Expand Down Expand Up @@ -2762,7 +2762,7 @@ func (wh *WorkflowHandler) ListClosedWorkflowExecutions(
WorkflowID: listRequest.ExecutionFilter.GetWorkflowId(),
})
}
wh.GetLogger().Info("List closed workflow with filter",
wh.GetLogger().Debug("List closed workflow with filter",
tag.WorkflowDomainName(listRequest.GetDomain()), tag.WorkflowListWorkflowFilterByID)
} else if listRequest.TypeFilter != nil {
if wh.config.DisableListVisibilityByFilter(domain) {
Expand All @@ -2773,7 +2773,7 @@ func (wh *WorkflowHandler) ListClosedWorkflowExecutions(
WorkflowTypeName: listRequest.TypeFilter.GetName(),
})
}
wh.GetLogger().Info("List closed workflow with filter",
wh.GetLogger().Debug("List closed workflow with filter",
tag.WorkflowDomainName(listRequest.GetDomain()), tag.WorkflowListWorkflowFilterByType)
} else if listRequest.StatusFilter != nil {
if wh.config.DisableListVisibilityByFilter(domain) {
Expand All @@ -2784,7 +2784,7 @@ func (wh *WorkflowHandler) ListClosedWorkflowExecutions(
Status: listRequest.GetStatusFilter(),
})
}
wh.GetLogger().Info("List closed workflow with filter",
wh.GetLogger().Debug("List closed workflow with filter",
tag.WorkflowDomainName(listRequest.GetDomain()), tag.WorkflowListWorkflowFilterByStatus)
} else {
persistenceResp, err = wh.GetVisibilityManager().ListClosedWorkflowExecutions(&baseReq)
Expand Down
4 changes: 2 additions & 2 deletions service/history/failover/coordinator.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -138,7 +138,7 @@ func (c *coordinatorImpl) Start() {
go c.receiveFailoverMarkersLoop()
go c.notifyFailoverMarkerLoop()

c.logger.Info("", tag.LifeCycleStarted)
c.logger.Info("Coordinator state changed", tag.LifeCycleStarted)
}

func (c *coordinatorImpl) Stop() {
Expand All @@ -152,7 +152,7 @@ func (c *coordinatorImpl) Stop() {
}

close(c.shutdownChan)
c.logger.Info("", tag.LifeCycleStopped)
c.logger.Info("Coordinator state changed", tag.LifeCycleStopped)
}

func (c *coordinatorImpl) NotifyFailoverMarkers(
Expand Down
4 changes: 2 additions & 2 deletions service/history/failover/marker_notifier.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,7 +79,7 @@ func (m *markerNotifierImpl) Start() {
}

go m.notifyPendingFailoverMarker()
m.logger.Info("", tag.LifeCycleStarted)
m.logger.Info("Marker notifier state changed", tag.LifeCycleStarted)
}

func (m *markerNotifierImpl) Stop() {
Expand All @@ -92,7 +92,7 @@ func (m *markerNotifierImpl) Stop() {
return
}
close(m.shutdownCh)
m.logger.Info("", tag.LifeCycleStopped)
m.logger.Info("Marker notifier state changed", tag.LifeCycleStopped)
}

func (m *markerNotifierImpl) notifyPendingFailoverMarker() {
Expand Down
10 changes: 5 additions & 5 deletions service/history/historyEngine.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -384,8 +384,8 @@ func NewEngineWithShardContext(
// Make sure all the components are loaded lazily so start can return immediately. This is important because
// ShardController calls start sequentially for all the shards for a given host during startup.
func (e *historyEngineImpl) Start() {
e.logger.Info("", tag.LifeCycleStarting)
defer e.logger.Info("", tag.LifeCycleStarted)
e.logger.Info("History engine state changed", tag.LifeCycleStarting)
defer e.logger.Info("History engine state changed", tag.LifeCycleStarted)

e.registerDomainFailoverCallback()

Expand All @@ -407,8 +407,8 @@ func (e *historyEngineImpl) Start() {

// Stop the service.
func (e *historyEngineImpl) Stop() {
e.logger.Info("", tag.LifeCycleStopping)
defer e.logger.Info("", tag.LifeCycleStopped)
e.logger.Info("History engine state changed", tag.LifeCycleStopping)
defer e.logger.Info("History engine state changed", tag.LifeCycleStopped)

e.txProcessor.Stop()
e.timerProcessor.Stop()
Expand Down Expand Up @@ -1327,7 +1327,7 @@ func (e *historyEngineImpl) queryDirectlyThroughMatching(
return nil, err
}

e.logger.Info("query directly through matching on sticky timed out, attempting to query on non-sticky",
e.logger.Debug("query directly through matching on sticky timed out, attempting to query on non-sticky",
tag.WorkflowDomainName(queryRequest.GetDomain()),
tag.WorkflowID(queryRequest.Execution.GetWorkflowId()),
tag.WorkflowRunID(queryRequest.Execution.GetRunId()),
Expand Down
8 changes: 4 additions & 4 deletions service/history/queue/timer_queue_processor_base.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -148,8 +148,8 @@ func (t *timerQueueProcessorBase) Start() {
return
}

t.logger.Info("", tag.LifeCycleStarting)
defer t.logger.Info("", tag.LifeCycleStarted)
t.logger.Info("Timer queue processor state changed", tag.LifeCycleStarting)
defer t.logger.Info("Timer queue processor state changed", tag.LifeCycleStarted)
Comment on lines +151 to +152
Copy link
Contributor

@yycptt yycptt Aug 25, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think in most cases we use empty log message because the logger is already tagged with component tag which we can use for searching.

Is the idea here to provide an easier way to find all types of life cycle change events for a certain component?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Exactly. I realized that the intent was to rely on the tag, but there are several types of logs with the same lifecycle event tag values although they are unrelated and it is cumbersome to narrow down the logs to a specific component.

The message field is one of the most frequently used fields to filter logs during an investigation, and I don't think it's a good experience to have a good chunk of logs that have the same message (null) even though they are unrelated.


t.redispatcher.Start()

Expand All @@ -166,8 +166,8 @@ func (t *timerQueueProcessorBase) Stop() {
return
}

t.logger.Info("", tag.LifeCycleStopping)
defer t.logger.Info("", tag.LifeCycleStopped)
t.logger.Info("Timer queue processor state changed", tag.LifeCycleStopping)
defer t.logger.Info("Timer queue processor state changed", tag.LifeCycleStopped)

t.timerGate.Close()
close(t.shutdownCh)
Expand Down
8 changes: 4 additions & 4 deletions service/history/queue/transfer_queue_processor_base.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -129,8 +129,8 @@ func (t *transferQueueProcessorBase) Start() {
return
}

t.logger.Info("", tag.LifeCycleStarting)
defer t.logger.Info("", tag.LifeCycleStarted)
t.logger.Info("Transfer queue processor state changed", tag.LifeCycleStarting)
defer t.logger.Info("Transfer queue processor state changed", tag.LifeCycleStarted)

t.redispatcher.Start()

Expand All @@ -147,8 +147,8 @@ func (t *transferQueueProcessorBase) Stop() {
return
}

t.logger.Info("", tag.LifeCycleStopping)
defer t.logger.Info("", tag.LifeCycleStopped)
t.logger.Info("Transfer queue processor state changed", tag.LifeCycleStopping)
defer t.logger.Info("Transfer queue processor state changed", tag.LifeCycleStopped)

t.nextPollTimer.Close()
close(t.shutdownCh)
Expand Down
10 changes: 5 additions & 5 deletions service/history/queueProcessor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -167,8 +167,8 @@ func (p *queueProcessorBase) Start() {
return
}

p.logger.Info("", tag.LifeCycleStarting)
defer p.logger.Info("", tag.LifeCycleStarted)
p.logger.Info("Queue processor state changed", tag.LifeCycleStarting)
defer p.logger.Info("Queue processor state changed", tag.LifeCycleStarted)

if p.taskProcessor != nil {
p.taskProcessor.start()
Expand All @@ -186,8 +186,8 @@ func (p *queueProcessorBase) Stop() {
return
}

p.logger.Info("", tag.LifeCycleStopping)
defer p.logger.Info("", tag.LifeCycleStopped)
p.logger.Info("Queue processor state changed", tag.LifeCycleStopping)
defer p.logger.Info("Queue processor state changed", tag.LifeCycleStopped)

close(p.shutdownCh)
p.retryTasks()
Expand Down Expand Up @@ -271,7 +271,7 @@ processorPumpLoop:
}
}

p.logger.Info("Queue processor pump shut down.")
p.logger.Debug("Queue processor pump shut down.")
}

func (p *queueProcessorBase) processBatch() {
Expand Down
8 changes: 4 additions & 4 deletions service/history/replication/task_processor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -168,21 +168,21 @@ func (p *taskProcessorImpl) Stop() {
return
}

p.logger.Info("ReplicationTaskProcessor shutting down.")
p.logger.Debug("ReplicationTaskProcessor shutting down.")
close(p.done)
}

func (p *taskProcessorImpl) processorLoop() {
defer func() {
p.logger.Info("Closing replication task processor.", tag.ReadLevel(p.lastRetrievedMessageID))
p.logger.Debug("Closing replication task processor.", tag.ReadLevel(p.lastRetrievedMessageID))
}()

Loop:
for {
// for each iteration, do close check first
select {
case <-p.done:
p.logger.Info("ReplicationTaskProcessor shutting down.")
p.logger.Debug("ReplicationTaskProcessor shutting down.")
return
default:
}
Expand Down Expand Up @@ -580,7 +580,7 @@ func (p *taskProcessorImpl) shouldRetryDLQ(err error) bool {

select {
case <-p.done:
p.logger.Info("ReplicationTaskProcessor shutting down.")
p.logger.Debug("ReplicationTaskProcessor shutting down.")
return false
default:
return true
Expand Down
24 changes: 12 additions & 12 deletions service/history/shard/controller.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -163,7 +163,7 @@ func (c *controller) Start() {
c.logger.Error("Error adding listener", tag.Error(err))
}

c.logger.Info("", tag.LifeCycleStarted)
c.logger.Info("Shard controller state changed", tag.LifeCycleStarted)
}

func (c *controller) Stop() {
Expand All @@ -182,7 +182,7 @@ func (c *controller) Stop() {
c.logger.Warn("", tag.LifeCycleStopTimedout)
}

c.logger.Info("", tag.LifeCycleStopped)
c.logger.Info("Shard controller state changed", tag.LifeCycleStopped)
}

func (c *controller) PrepareToStop() {
Expand Down Expand Up @@ -250,7 +250,7 @@ func (c *controller) removeEngineForShard(shardID int, shardItem *historyShardsI

func (c *controller) shardClosedCallback(shardID int, shardItem *historyShardsItem) {
c.metricsScope.IncCounter(metrics.ShardClosedCounter)
c.logger.Info("", tag.LifeCycleStopping, tag.ComponentShard, tag.ShardID(shardID))
c.logger.Info("Shard controller state changed", tag.LifeCycleStopping, tag.ComponentShard, tag.ShardID(shardID))
c.removeEngineForShard(shardID, shardItem)
}

Expand Down Expand Up @@ -296,7 +296,7 @@ func (c *controller) getOrCreateHistoryShardItem(shardID int) (*historyShardsIte
c.historyShards[shardID] = shardItem
c.metricsScope.IncCounter(metrics.ShardItemCreatedCounter)

shardItem.logger.Info("", tag.LifeCycleStarted, tag.ComponentShardItem)
shardItem.logger.Info("Shard item state changed", tag.LifeCycleStarted, tag.ComponentShardItem)
return shardItem, nil
}

Expand All @@ -323,7 +323,7 @@ func (c *controller) removeHistoryShardItem(shardID int, shardItem *historyShard

c.metricsScope.IncCounter(metrics.ShardItemRemovedCounter)

currentShardItem.logger.Info("", tag.LifeCycleStopped, tag.ComponentShardItem, tag.Number(int64(nShards)))
currentShardItem.logger.Info("Shard item state changed", tag.LifeCycleStopped, tag.ComponentShardItem, tag.Number(int64(nShards)))
return currentShardItem, nil
}

Expand Down Expand Up @@ -352,7 +352,7 @@ func (c *controller) shardManagementPump() {
case changedEvent := <-c.membershipUpdateCh:
c.metricsScope.IncCounter(metrics.MembershipChangedCounter)

c.logger.Info("", tag.ValueRingMembershipChangedEvent,
c.logger.Info("Ring membership changed", tag.ValueRingMembershipChangedEvent,
tag.NumberProcessed(len(changedEvent.HostsAdded)),
tag.NumberDeleted(len(changedEvent.HostsRemoved)),
tag.Number(int64(len(changedEvent.HostsUpdated))))
Expand Down Expand Up @@ -408,7 +408,7 @@ func (c *controller) acquireShards() {
}

func (c *controller) doShutdown() {
c.logger.Info("", tag.LifeCycleStopping)
c.logger.Info("Shard controller state changed", tag.LifeCycleStopping)
c.Lock()
defer c.Unlock()
for _, item := range c.historyShards {
Expand All @@ -435,12 +435,12 @@ func (i *historyShardsItem) getOrCreateEngine(
defer i.Unlock()
switch i.status {
case historyShardsItemStatusInitialized:
i.logger.Info("", tag.LifeCycleStarting, tag.ComponentShardEngine)
i.logger.Info("Shard engine state changed", tag.LifeCycleStarting, tag.ComponentShardEngine)
context, err := acquireShard(i, closeCallback)
if err != nil {
// invalidate the shardItem so that the same shardItem won't be
// used to create another shardContext
i.logger.Info("", tag.LifeCycleStopped, tag.ComponentShardEngine)
i.logger.Info("Shard engine state changed", tag.LifeCycleStopped, tag.ComponentShardEngine)
i.status = historyShardsItemStatusStopped
return nil, err
}
Expand All @@ -450,7 +450,7 @@ func (i *historyShardsItem) getOrCreateEngine(
}
i.engine = i.engineFactory.CreateEngine(context)
i.engine.Start()
i.logger.Info("", tag.LifeCycleStarted, tag.ComponentShardEngine)
i.logger.Info("Shard engine state changed", tag.LifeCycleStarted, tag.ComponentShardEngine)
i.status = historyShardsItemStatusStarted
return i.engine, nil
case historyShardsItemStatusStarted:
Expand All @@ -470,10 +470,10 @@ func (i *historyShardsItem) stopEngine() {
case historyShardsItemStatusInitialized:
i.status = historyShardsItemStatusStopped
case historyShardsItemStatusStarted:
i.logger.Info("", tag.LifeCycleStopping, tag.ComponentShardEngine)
i.logger.Info("Shard engine state changed", tag.LifeCycleStopping, tag.ComponentShardEngine)
i.engine.Stop()
i.engine = nil
i.logger.Info("", tag.LifeCycleStopped, tag.ComponentShardEngine)
i.logger.Info("Shard engine state changed", tag.LifeCycleStopped, tag.ComponentShardEngine)
i.status = historyShardsItemStatusStopped
case historyShardsItemStatusStopped:
// no op
Expand Down
2 changes: 1 addition & 1 deletion service/history/taskProcessor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -137,7 +137,7 @@ func (t *taskProcessor) stop() {
if success := common.AwaitWaitGroup(&t.workerWG, time.Minute); !success {
t.logger.Warn("Task processor timed out on shutdown.")
}
t.logger.Info("Task processor shutdown.")
t.logger.Debug("Task processor shutdown.")
}

func (t *taskProcessor) taskWorker(
Expand Down
4 changes: 2 additions & 2 deletions service/history/timerQueueProcessorBase.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -199,7 +199,7 @@ func (t *timerQueueProcessorBase) Stop() {
}
t.redispatcher.Stop()

t.logger.Info("Timer queue processor stopped.")
t.logger.Debug("Timer queue processor stopped.")
}

func (t *timerQueueProcessorBase) processorPump() {
Expand All @@ -218,7 +218,7 @@ RetryProcessor:
}
}

t.logger.Info("Timer queue processor pump shutting down.")
t.logger.Debug("Timer queue processor pump shutting down.")
}

// NotifyNewTimers - Notify the processor about the new timer events arrival.
Expand Down
8 changes: 4 additions & 4 deletions service/matching/matchingEngine.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -179,21 +179,21 @@ func (e *matchingEngineImpl) getTaskListManager(taskList *taskListID,
e.taskListsLock.Unlock()
return result, nil
}
e.logger.Info("", tag.LifeCycleStarting, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType))
e.logger.Info("Task list manager state changed", tag.LifeCycleStarting, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType))
mgr, err := newTaskListManager(e, taskList, taskListKind, e.config)
if err != nil {
e.taskListsLock.Unlock()
e.logger.Info("", tag.LifeCycleStartFailed, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType), tag.Error(err))
e.logger.Info("Task list manager state changed", tag.LifeCycleStartFailed, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType), tag.Error(err))
return nil, err
}
e.taskLists[*taskList] = mgr
e.taskListsLock.Unlock()
err = mgr.Start()
if err != nil {
e.logger.Info("", tag.LifeCycleStartFailed, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType), tag.Error(err))
e.logger.Info("Task list manager state changed", tag.LifeCycleStartFailed, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType), tag.Error(err))
return nil, err
}
e.logger.Info("", tag.LifeCycleStarted, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType))
e.logger.Info("Task list manager state changed", tag.LifeCycleStarted, tag.WorkflowTaskListName(taskList.name), tag.WorkflowTaskListType(taskList.taskType))
return mgr, nil
}

Expand Down
2 changes: 1 addition & 1 deletion service/matching/taskListManager.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -205,7 +205,7 @@ func (c *taskListManagerImpl) Stop() {
c.taskWriter.Stop()
c.taskReader.Stop()
c.engine.removeTaskListManager(c.taskListID)
c.logger.Info("", tag.LifeCycleStopped)
c.logger.Info("Task list manager state changed", tag.LifeCycleStopped)
}

// AddTask adds a task to the task list. This method will first attempt a synchronous
Expand Down
Loading