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

Add logging around heartbeats #3628

Merged
merged 2 commits into from
Dec 7, 2017
Merged

Add logging around heartbeats #3628

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
a540a0b
Add logging around heartbeats
dadgar Dec 7, 2017
77fe78c
Drop trace logging
dadgar Dec 7, 2017
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
35 changes: 25 additions & 10 deletions client/client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -113,9 +113,10 @@ type Client struct {
servers *serverlist

// heartbeat related times for tracking how often to heartbeat
lastHeartbeat time.Time
heartbeatTTL time.Duration
heartbeatLock sync.Mutex
lastHeartbeat time.Time
Copy link
Contributor

Choose a reason for hiding this comment

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

Maybe have a heartbeat struct instead of all of these as direct fields on the client?

heartbeatTTL time.Duration
haveHeartbeated bool
heartbeatLock sync.Mutex

// triggerDiscoveryCh triggers Consul discovery; see triggerDiscovery
triggerDiscoveryCh chan struct{}
Expand Down Expand Up @@ -1187,9 +1188,7 @@ func (c *Client) registerNode() error {

// updateNodeStatus is used to heartbeat and update the status of the node
func (c *Client) updateNodeStatus() error {
c.heartbeatLock.Lock()
defer c.heartbeatLock.Unlock()

start := time.Now()
req := structs.NodeUpdateStatusRequest{
NodeID: c.NodeID(),
Status: structs.NodeStatusReady,
Expand All @@ -1200,16 +1199,32 @@ func (c *Client) updateNodeStatus() error {
c.triggerDiscovery()
return fmt.Errorf("failed to update status: %v", err)
}
end := time.Now()

if len(resp.EvalIDs) != 0 {
c.logger.Printf("[DEBUG] client: %d evaluations triggered by node update", len(resp.EvalIDs))
}
if resp.Index != 0 {
c.logger.Printf("[DEBUG] client: state updated to %s", req.Status)
}

// Update heartbeat time and ttl
// Update the last heartbeat and the new TTL, capturing the old values
c.heartbeatLock.Lock()
Copy link
Contributor

Choose a reason for hiding this comment

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

This could be extracted into a function on a heartbeat struct.

last := c.lastHeartbeat
oldTTL := c.heartbeatTTL
haveHeartbeated := c.haveHeartbeated
c.lastHeartbeat = time.Now()
c.heartbeatTTL = resp.HeartbeatTTL
c.haveHeartbeated = true
c.heartbeatLock.Unlock()
c.logger.Printf("[TRACE] client: next heartbeat in %v", resp.HeartbeatTTL)

if resp.Index != 0 {
c.logger.Printf("[DEBUG] client: state updated to %s", req.Status)

// We have potentially missed our TTL log how delayed we were
if haveHeartbeated {
c.logger.Printf("[WARN] client: heartbeat missed (request took %v). Heartbeat TTL was %v and heartbeated after %v",
end.Sub(start), oldTTL, time.Since(last))
}
}

// Convert []*NodeServerInfo to []*endpoints
localdc := c.Datacenter()
Expand Down