Fixed https://github.com/aws/amazon-ecs-agent/issues/506 #652

liwenwu-amazon · 2016-12-29T22:58:38Z

Summary

Fix issue #506

Implementation details

1 . Add a new field 'lastResetTime' to stats Queue struct, Set 'lastResetTime' whenever Reseting the Queue.
2. With 1, the caller can return an error if queue has NOT been filled with expected data points after a resetThreshold period
3. define a new error code engine.EmptyMetricsError, so that the caller can ignore this error when publishing metrics immediately after agent connect to backend. And return/handle this error in other situations.

Testing

Builds on Linux (make release)
Builds on Windows (go build -out amazon-ecs-agent.exe ./agent)
Unit tests on Linux (make test) pass
Unit tests on Windows (go test -timeout=25s ./agent/...) pass
Integration tests on Linux (make run-integ-tests) pass
Integration tests on Windows (.\scripts\run-integ-tests.ps1) pass
Functional tests on Linux (make run-functional-tests) pass
Functional tests on Windows (.\scripts\run-functional-tests.ps1) pass

New tests cover the changes:

Description for the changelog

Licensing

This contribution is under the terms of the Apache 2.0 License:

@richardpen @samuelkarp @aaithal

aaithal

Can you also check why the functional tests failed with this commit?

aaithal · 2017-01-03T17:28:24Z

agent/stats/engine.go

@@ -35,6 +36,7 @@ import (
 const (
 	containerChangeHandler = "DockerStatsEngineDockerEventsHandler"
 	listContainersTimeout  = 10 * time.Minute
+	resetThreshold         = 2 * ecsengine.StatsInactivityTimeout


Can you rename this to be more descriptive? queueResetThreshold perhaps?

aaithal · 2017-01-03T17:28:48Z

agent/stats/engine.go

@@ -398,6 +401,13 @@ func (engine *DockerStatsEngine) getContainerMetricsForTask(taskArn string) ([]*
 			engine.doRemoveContainer(container, taskArn)
 			continue
 		}
+
+		if !container.statsQueue.resetThreshholdElapsed(resetThreshold) &&


Typo: resetThreshholdElapsed -> resetThresholdElapsed

aaithal · 2017-01-03T17:30:18Z

agent/stats/queue.go

@@ -133,6 +137,19 @@ func getMemoryUsagePerc(s *UsageStats) float64 {

 type getUsageFunc func(*UsageStats) float64

+func (queue *Queue) resetThreshholdElapsed(timeOut time.Duration) bool {


this should be timeout and not timeOut.

aaithal · 2017-01-03T17:31:47Z

agent/stats/queue_test.go

+
+	queue.Reset()
+
+	threshholdElapsed := queue.resetThreshholdElapsed(2 * time.Millisecond)


typo: threshholdElapsed -> thresholdElapsed

aaithal · 2017-01-03T17:32:28Z

agent/stats/queue_test.go

+	queue.Reset()
+
+	threshholdElapsed := queue.resetThreshholdElapsed(2 * time.Millisecond)
+	if threshholdElapsed {


Can you use assert.False() instead of this?

aaithal · 2017-01-03T17:33:40Z

agent/stats/queue_test.go

+	time.Sleep(3 * time.Millisecond)
+	threshholdElapsed = queue.resetThreshholdElapsed(2 * time.Millisecond)
+
+	if !threshholdElapsed {


Same here. Please use the github.com/stretchr/testify/assert package's True() method here as well.

aaithal · 2017-01-03T17:34:30Z

agent/stats/queue_test.go

+	queue := NewQueue(queueLength)
+
+	enoughDataPoints := queue.enoughDatapointsInBuffer()
+	if enoughDataPoints {


Please use assert.False() here.

aaithal · 2017-01-03T17:34:42Z

agent/stats/queue_test.go

+	}
+
+	enoughDataPoints = queue.enoughDatapointsInBuffer()
+	if !enoughDataPoints {


Please use assert.True() here.

aaithal · 2017-01-03T17:37:17Z

agent/tcs/client/client.go

@@ -164,6 +170,7 @@ func (cs *clientServer) publishMetricsOnce() {
 			seelog.Warnf("Error publishing metrics: %v. Request: %v", err, request)


Shouldn't this return the error immediately as well?

aaithal · 2017-01-04T17:05:06Z

agent/tcs/client/client.go

-	cs.publishMetricsOnce()
+	err := cs.publishMetricsOnce()
+	if err != nil && err != stats.EmptyMetricsError {
+		seelog.Warnf("Error getting instance metrics: %v", err)


Can you rephrase the error message? The error is from the the publishMetricsOnce() method. We can't be sure here if its because of publish failing or if there was an error getting metrics.

aaithal · 2017-01-04T17:05:32Z

agent/tcs/client/client.go

-			cs.publishMetricsOnce()
+			err := cs.publishMetricsOnce()
+			if err != nil {
+				seelog.Warnf("Error getting instance metrics: %v", err)


Same as above, can you rephrase the error message?

aaithal · 2017-01-04T17:05:56Z

agent/tcs/client/client.go

 		case <-cs.endPublish:
 			return
 		}
 	}
 }

 // publishMetricsOnce is invoked by the ticker to periodically publish metrics to backend.
-func (cs *clientServer) publishMetricsOnce() {
+func (cs *clientServer) publishMetricsOnce() error {


Can you add/update unit tests to cover this change?

Also, the functional tests for windows seem to have stuck. Can you address that and make sure those pass as well?

Opened issue #663 and #662 to track unit-test failure on windows platform

samuelkarp

Can you fix your pull request summary formatting? The checkboxes look malformed.

samuelkarp · 2017-01-10T22:55:24Z

agent/acs/handler/acs_handler_test.go

@@ -519,7 +519,7 @@ func TestHandlerReconnectDelayForInactiveInstanceError(t *testing.T) {
 		mockWsClient.EXPECT().Connect().Do(func() {
 			reconnectDelay := time.Now().Sub(firstConnectionAttemptTime)
 			t.Logf("Delay between successive connections: %v", reconnectDelay)
-			if reconnectDelay < inactiveInstanceReconnectDelay {
+			if reconnectDelay+1 < inactiveInstanceReconnectDelay {


Why +1? Do you really mean to say reconnectDelay <= inactiveInstanceReconnectDelay?

The assertion error message also looks wrong. It should probably read "Reconnect delay %v is less than inactive instance reconnect delay %v".

On Window platform, we find intermittently that time.Now().Sub(...) can returns 199.9989ms even after code waiting for time.NewTimer(200) ms

Rather than blindly adding 1, can you:

Include this information about intermittent time subtraction issues in an explanatory comment

Explicitly allow for some slop in the assertion here (possibly up to 1ms?) by adjusting the expected time rather than the observed time and having a named value instead of a literal (use a constant or variable to describe the modifier).

samuelkarp · 2017-01-10T23:20:16Z

agent/stats/engine.go

@@ -398,6 +401,13 @@ func (engine *DockerStatsEngine) getContainerMetricsForTask(taskArn string) ([]*
 			engine.doRemoveContainer(container, taskArn)
 			continue
 		}
+
+		if !container.statsQueue.resetThresholdElapsed(queueResetThreshold) &&


I find this conditional pretty hard to read. I think it might be easier like this:

if !container.statsQueue.enoughDatapointsInBuffer() && !container.statsQueue.resetThresholdElapsed(queueResetThreshold)

That lets it read more logically as "if there are not enough datapoints and the threshold is not elapsed".

samuelkarp · 2017-01-10T23:21:09Z

agent/tcs/client/client_test.go

@@ -152,6 +158,18 @@ func TestPublishMetricsRequest(t *testing.T) {

 	cs.Close()
 }
+func TestPublishMetricsOnceEmptyStatsError(t *testing.T) {
+


stray empty line

samuelkarp · 2017-01-12T22:59:50Z

agent/acs/handler/acs_handler_test.go

@@ -519,8 +519,10 @@ func TestHandlerReconnectDelayForInactiveInstanceError(t *testing.T) {
 		mockWsClient.EXPECT().Connect().Do(func() {
 			reconnectDelay := time.Now().Sub(firstConnectionAttemptTime)
 			t.Logf("Delay between successive connections: %v", reconnectDelay)
-			if reconnectDelay < inactiveInstanceReconnectDelay {
-				t.Errorf("Reconnect delay %v is not less than inactive instance reconnect delay %v", reconnectDelay, inactiveInstanceReconnectDelay)
+			// On window platform, we found issue with time.Now().Sub(...) reporting 199.9989 even after the code has already waited for time.NewTimer(200)ms.


s/window/Windows/

samuelkarp · 2017-01-12T23:00:42Z

agent/acs/handler/acs_handler_test.go

-				t.Errorf("Reconnect delay %v is not less than inactive instance reconnect delay %v", reconnectDelay, inactiveInstanceReconnectDelay)
+			// On window platform, we found issue with time.Now().Sub(...) reporting 199.9989 even after the code has already waited for time.NewTimer(200)ms.
+			timeSubFuncSlopAllowed := 1 * time.Millisecond
+			if reconnectDelay+timeSubFuncSlopAllowed < inactiveInstanceReconnectDelay {


Can you change this to reconnectDelay < inactiveInstanceReconnectDelay - timeSubFuncSlopAllowed?

samuelkarp · 2017-01-12T23:16:08Z

agent/tcs/client/client_test.go

+	}
+	err := cs.publishMetricsOnce()
+
+	if err == nil {


assert.NoError(err)

samuelkarp · 2017-01-12T23:16:23Z

agent/tcs/client/client_test.go

+	err := cs.publishMetricsOnce()
+
+	if err == nil {
+		t.Error("Failed: expecting publishMerticOnce return err ")


s/Mertic/Metric/

aaithal

Can you also make sure that copyright headers are up to date with the year 2017 in all of the files?

aaithal · 2017-01-13T18:22:49Z

agent/acs/handler/acs_handler_test.go

-			if reconnectDelay < inactiveInstanceReconnectDelay {
-				t.Errorf("Reconnect delay %v is not less than inactive instance reconnect delay %v", reconnectDelay, inactiveInstanceReconnectDelay)
+			// On window platform, we found issue with time.Now().Sub(...) reporting 199.9989 even after the code has already waited for time.NewTimer(200)ms.
+			timeSubFuncSlopAllowed := 1 * time.Millisecond


I'm not a fan of doing this math here. Can you please use assert.WithinDuration instead? https://godoc.org/github.com/stretchr/testify/assert#Assertions.WithinDuration

Writing less code is always better :)

aaithal · 2017-01-13T18:23:53Z

agent/stats/queue_test.go

+	assert.True(t, thresholdElapsed, "Queue is expected to elapse the threshold")
+
+}
+func TestEnoughDatapointsInBuffer(t *testing.T) {


nit: new line needed

aaithal · 2017-01-16T20:11:33Z

agent/acs/handler/acs_handler_test.go

-			if reconnectDelay < inactiveInstanceReconnectDelay-timeSubFuncSlopAllowed {
-				t.Errorf("Reconnect delay %v is 1 ms less than inactive instance reconnect delay %v", reconnectDelay, inactiveInstanceReconnectDelay)
+			// On window platform, we found issue with time.Now().Sub(...) reporting 199.9989 even after the code has already waited for time.NewTimer(200)ms.
+			if reconnectDelay < inactiveInstanceReconnectDelay {


I don't think you need this if block when using assert.WithinDuration

There are 2 conditions here

to make sure reconnectDelay is "greater" than inactiveInstanceReconnectDelay

or to make sure it is within duration of the 1 milisecond, if reconnectDelay is "less" than inactiveinstanceReconnectDelay
The code here is intended for "1"

I don't think that's entirely correct. I think the intention is to ensure that we wait for inactiveInstanceReconnectDelay between disconnects. It's >= inactiveInstanceReconnectDelay. We don't add any jitter when the disconnection is for an inactive instance. So, assert.WithinDuration() should be good enough with a buffer of 2ms.

aaithal · 2017-01-16T20:13:02Z

agent/stats/engine.go

+
+		if !container.statsQueue.enoughDatapointsInBuffer() &&
+			!container.statsQueue.resetThresholdElapsed(queueResetThreshold) {
+			seelog.Debug("Stats not ready for container %s", dockerID)


aaithal

Tests are still failing. Please ensure that they succeed with the next revision.

aaithal · 2017-01-18T23:16:03Z

agent/acs/handler/acs_handler_test.go

-				t.Errorf("Reconnect delay %v is not less than inactive instance reconnect delay %v", reconnectDelay, inactiveInstanceReconnectDelay)
-			}
+			timeSubFuncSlopAllowed := 2 * time.Millisecond
+			// On window platform, we found issue with time.Now().Sub(...) reporting 199.9989 even after the code has already waited for time.NewTimer(200)ms.


As @samuelkarp mentioned in one of the earlier comments, there's no "window platform", please modify that. Also, please split the comment across multiple lines to reduce the line width.

aaithal · 2017-01-18T23:18:53Z

agent/stats/queue_test.go

+	queue.Reset()
+
+	thresholdElapsed := queue.resetThresholdElapsed(2 * time.Millisecond)
+	assert.False(t, thresholdElapsed, "Queue is NOT expected to elapsed the threshold right after reset")


I don't think the phrasing is correct here. The Queue does not elapse any threshold as it's not an entity that is time-bound. I think the better message here is "Queue reset threshold is not expected to elapse right after reset"

aaithal · 2017-01-18T23:19:44Z

agent/stats/queue_test.go

+	time.Sleep(3 * time.Millisecond)
+	thresholdElapsed = queue.resetThresholdElapsed(2 * time.Millisecond)
+
+	assert.True(t, thresholdElapsed, "Queue is expected to elapse the threshold")


Same as above. I think the better message here is "Queue reset threshold is expected to elapse after waiting"

aaithal · 2017-01-18T23:20:35Z

agent/stats/queue_test.go

+	queue := NewQueue(queueLength)
+
+	enoughDataPoints := queue.enoughDatapointsInBuffer()
+	assert.False(t, enoughDataPoints, "Queue is expected NOT having enough data points right after creation")


Grammar: "Queue is expected to not have enough data ..."

aaithal · 2017-01-18T23:20:52Z

agent/stats/queue_test.go

+
+	queue.Reset()
+	enoughDataPoints = queue.enoughDatapointsInBuffer()
+	assert.False(t, enoughDataPoints, "Queue is expected NOT having enough data points right after RESET")


Grammar: "Queue is expected to not have enough data ..."

samuelkarp · 2017-01-23T19:11:59Z

agent/acs/handler/acs_handler_test.go

+			// On windows platform, we found issue with time.Now().Sub(...) reporting 199.9989 even
+			// after the code has already waited for time.NewTimer(200)ms.
+			assert.WithinDuration(t, reconnectDelayTime, firstConnectionAttemptTime.Add(inactiveInstanceReconnectDelay), timeSubFuncSlopAllowed,
+				"Reconnect delay %v is expected within %v of inactive instance reconnect delay %v",


You don't need a message this detailed; the assert library will do this for you.

You mean

I should remove comment (line 524 to line 525)?
or

rewording remove line 527?
thanks

Reword line 527 and remove the format string. To see what I mean, you can temporarily make the assertion fail on your local machine and observe the error message that gets printed out.

aaithal · 2017-01-24T16:38:56Z

@liwenwu-amazon I think the code changes look good. Can you manually test if this fix has any side-effects on a long-running (1h) agent? We basically want to verify that:

Disconnect/Reconnect to ACS and TACS keep happening on a long running ECS Agent
Service/Cluster stats have a consistent value for a fixed workload on a long running ECS Agent

liwenwu-amazon · 2017-01-30T21:37:45Z

I have this image running for past 6 days. So far, I have not seen any warning messages. Nor I have seen any abnormal stats on "Metrics" dashboard on AWS console.

The CPUUtilization is kept at 0.03% average and few spikes maxed @ 0.2% . The CPU Reservation is stabilized at 50%. The MemoryUtilization is stabilized at 6% and memoryreservation is stabilized at 27%

liwenwu-amazon force-pushed the issue506 branch from 03fb48c to eb96940 Compare December 29, 2016 23:16

aaithal requested changes Jan 3, 2017

View reviewed changes

liwenwu-amazon force-pushed the issue506 branch from eb96940 to 0dd2e89 Compare January 3, 2017 19:48

aaithal requested changes Jan 4, 2017

View reviewed changes

liwenwu-amazon force-pushed the issue506 branch 3 times, most recently from eb31f63 to 1508e15 Compare January 5, 2017 07:46

samuelkarp reviewed Jan 10, 2017

View reviewed changes

liwenwu-amazon force-pushed the issue506 branch 3 times, most recently from 56721da to 6d41ad1 Compare January 11, 2017 01:53

samuelkarp reviewed Jan 12, 2017

View reviewed changes

aaithal reviewed Jan 13, 2017

View reviewed changes

aaithal reviewed Jan 16, 2017

View reviewed changes

aaithal reviewed Jan 18, 2017

View reviewed changes

samuelkarp reviewed Jan 23, 2017

View reviewed changes

aaithal approved these changes Jan 30, 2017

View reviewed changes

samuelkarp approved these changes Jan 30, 2017

View reviewed changes

Fixed aws#506

1be5420

liwenwu-amazon force-pushed the issue506 branch from 628e68c to 1be5420 Compare January 31, 2017 00:59

liwenwu-amazon merged commit 1be5420 into aws:dev Jan 31, 2017

samuelkarp added this to the 1.14.1 milestone Feb 1, 2017

		@@ -133,6 +137,19 @@ func getMemoryUsagePerc(s *UsageStats) float64 {

		type getUsageFunc func(*UsageStats) float64

		func (queue *Queue) resetThreshholdElapsed(timeOut time.Duration) bool {


		queue.Reset()

		threshholdElapsed := queue.resetThreshholdElapsed(2 * time.Millisecond)

		@@ -164,6 +170,7 @@ func (cs *clientServer) publishMetricsOnce() {
		seelog.Warnf("Error publishing metrics: %v. Request: %v", err, request)

Fixed https://github.com/aws/amazon-ecs-agent/issues/506 #652

Fixed https://github.com/aws/amazon-ecs-agent/issues/506 #652

Conversation

liwenwu-amazon commented Dec 29, 2016 • edited by samuelkarp Loading

Summary

Implementation details

Testing

Description for the changelog

Licensing

aaithal left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal Jan 4, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

samuelkarp left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal commented Jan 24, 2017

liwenwu-amazon commented Jan 30, 2017

liwenwu-amazon commented Dec 29, 2016 •

edited by samuelkarp

Loading

aaithal Jan 4, 2017 •

edited

Loading

aaithal left a comment •

edited

Loading