Websocket timeout #993

aaithal · 2017-09-27T18:48:47Z

Summary

Implements some websocket connection management improvements.

Implementation details

Set read and write deadlines for websocket ReadMessage and
WriteMessage operations. This is to ensure that these methods
do not hang and result in io timeout if there's issues with
the connection
Reduce the scope of the lock in the Connect() method. The
lock was being held for the length of Connect() method, which
meant that it wouldn't be relnquished if there was any delay
in establishing the connection. The scope of the lock has now
been reduced to just accessing the cs.conn variable
Start ACS heartbeat timer after the connection has been
established. The timer was being started before a call to
Connect, which meant that the connection could be prematurely
terminated for being idle if there was a delay in establishing
the connection

Testing

New tests cover the changes: Yes

Description for the changelog

Covered in changelog.md

Licensing

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

The wc command prefixes spaces to the output, which corrupts the GIT_PORCELAIN variable, thus failing the build. This change removes spaces from the output.

This commit aims to make the websocker connection management better by implementing the following improvements: 1. Set read and write deadlines for websocket ReadMessage and WriteMessage operations. This is to ensure that these methods do not hang and result in io timeout if there's issues with the connection 2. Reduce the scope of the lock in the Connect() method. The lock was being held for the length of Connect() method, which meant that it wouldn't be relnquished if there was any delay in establishing the connection. The scope of the lock has now been reduced to just accessing the cs.conn variable 3. Start ACS heartbeat timer after the connection has been established. The timer was being started before a call to Connect, which meant that the connection could be prematurely terminated for being idle if there was a delay in establishing the connection These changes should improve the disconnection behavior of the websocket connection, which should help with scenarios where the Agent never reconnects to ACS because it's forever waiting in Disconnect() method waiting to acquire the lock (aws#985)

samuelkarp · 2017-09-27T19:48:53Z

agent/acs/handler/acs_handler.go

-		seelog.Debug("ACS activity occured")
+		seelog.Debug("ACS activity occurred")
+		// Reset read deadline as there's activity on the channel
+		if err := client.SetReadDeadline(time.Now().Add(heartbeatTimeout + heartbeatJitter)); err != nil {


I'd feel more comfortable if this were actually longer, like 2*heartbeatTimeout + heartbeatJitter.

Can you explain again here too? Doesn't doubling that have the net effect of doubling your pre-established heartbeatTimeout the first time there is some traffic over the websocket?

Because we use rand.Int63n() in AddJitter, heartbeatTimeout + heartbeatJitter should always be greater than the heartbeat duration that we compute. I think it should be safe to set it the way it's currently being set.

Doesn't doubling that have the net effect of doubling your pre-established heartbeatTimeout the first time there is some traffic over the websocket?

No, the deadline is set based on time.Now(), so it's always in the future by the amount specified here.

I think it should be safe to set it the way it's currently being set.

I'm worried, because this is a time and not a duration, and because Go 1.7 doesn't have a monotonic clock, that something unexpected can happen here. I'd feel more comfortable with a longer timeout because we don't expect this timeout to be hit anyway and I don't see any danger of making it longer.

Once we move to Go 1.9 there will be a monotonic clock and this should be safer.

I'd feel more comfortable with a longer timeout because we don't expect this timeout to be hit anyway

Oh, you'd be surprised :) I think we'll hit this timeout when there's connection issues. However, I do buy the argument that 2*heartbeatTimeout + heartbeatJitter will work for most cases here.

samuelkarp · 2017-09-27T19:49:06Z

agent/acs/handler/acs_handler.go

+			seelog.Warn("Unable to extend read deadline for ACS connection: %v", err)
+		}
+
+		// Reset heearbeat timer


nit: heartbeat

samuelkarp · 2017-09-27T20:12:55Z

agent/tcs/handler/handler.go

@@ -35,8 +36,8 @@ const (
 	defaultPublishMetricsInterval = 20 * time.Second

 	// The maximum time to wait between heartbeats without disconnecting
-	defaultHeartbeatTimeout            = 5 * time.Minute
-	defaultHeartbeatJitter             = 3 * time.Minute
+	defaultHeartbeatTimeout            = 1 * time.Minute


Why did we change these?

I assume this is just meant to mimic the work that @richardpen did for the ACS client.

@samuelkarp @jhaynes is correct. This is reflecting the change that @richardpen did.

samuelkarp · 2017-09-27T20:13:28Z

agent/tcs/handler/handler.go

+	return func(interface{}) {
+		seelog.Trace("TCS activity occured")
+		// Reset read deadline as there's activity on the channel
+		if err := client.SetReadDeadline(time.Now().Add(defaultHeartbeatTimeout + defaultHeartbeatJitter)); err != nil {


As above, I think this should be longer than just timeout + jitter.

samuelkarp · 2017-09-27T20:14:39Z

agent/acs/handler/acs_handler.go

@@ -377,7 +376,7 @@ func (acsSession *session) heartbeatJitter() time.Duration {

 // createACSClient creates the ACS Client using the specified URL
 func (acsResources *acsSessionResources) createACSClient(url string, cfg *config.Config) wsclient.ClientServer {
-	return acsclient.New(url, cfg, acsResources.credentialsProvider)
+	return acsclient.New(url, cfg, acsResources.credentialsProvider, heartbeatTimeout+heartbeatJitter)


I think this should be longer than timeout + jitter.

Can you expand on why? I would assume you'd want it to be smaller if anything. That way, you could retry a read/write without necessarily having to re-establish the whole connection.

Will respond on the other comment.

samuelkarp · 2017-09-27T20:14:54Z

agent/tcs/handler/handler.go

 	deregisterInstanceEventStream *eventstream.EventStream) error {
-	client := tcsclient.New(url, cfg, credentialProvider, statsEngine, publishMetricsInterval)
+	client := tcsclient.New(url, cfg, credentialProvider, statsEngine,
+		publishMetricsInterval, defaultHeartbeatTimeout+defaultHeartbeatJitter)


I think this should be longer than timeout + jitter.

richardpen · 2017-09-27T20:07:02Z

agent/acs/handler/acs_handler.go

+		seelog.Debug("ACS activity occurred")
+		// Reset read deadline as there's activity on the channel
+		if err := client.SetReadDeadline(time.Now().Add(heartbeatTimeout + heartbeatJitter)); err != nil {
+			seelog.Warn("Unable to extend read deadline for ACS connection: %v", err)


nit: Warnf

richardpen · 2017-09-27T20:10:11Z

agent/tcs/handler/handler.go

@@ -112,7 +118,7 @@ func startSession(url string, cfg *config.Config, credentialProvider *credential
 	timer := time.AfterFunc(utils.AddJitter(heartbeatTimeout, heartbeatJitter), func() {


Can you do the same as acs to move the timer after the connection was established?

Yeah, I thought I did that. But, obviously didn't. I'll modify this.

richardpen · 2017-09-27T20:15:10Z

agent/tcs/handler/handler.go

+// connection is active
+func anyMessageHandler(client wsclient.ClientServer) func(interface{}) {
+	return func(interface{}) {
+		seelog.Trace("TCS activity occured")


Is the Trace level here intentionally?

The similar ACS log line is Debug level.

TCS channel is more chatty, which means we'll see this printed every 20 seconds if this is changed to Debug. I could get rid of this altogether if you have a strong preference here. But, somehow this Trace soothes my mind.

richardpen · 2017-09-27T20:23:37Z

agent/wsclient/client.go

@@ -48,6 +49,9 @@ const (
 	// wsConnectTimeout specifies the default connection timeout to the backend.
 	wsConnectTimeout = 30 * time.Second

+	// wsHandshakeTimeout specifies the default handshake timeout for the websocket client
+	wsHandshakeTimeout = wsConnectTimeout


If we have wsHandshakeTimeout, do we still need wsConnectTimeout? As if the hand shake timed out, the connect will fail, is that right? Or they should be the same value, eg: wsHandshakeTimeout = 3*wsConnectTimeout

I would assume the wsHandshakeTimeout would be <= wsConectTimeout

richardpen · 2017-09-27T20:34:39Z

agent/wsclient/client.go

+// SetReadDeadline sets the read deadline for the websocket connection
+// A read timeout results in an io error if there are any outstanding reads
+// that exceed the deadline
+func (cs *ClientServerImpl) SetReadDeadline(t time.Time) error {


Would it be better to pass the duration and calculate the time right before calling the SetReadDeadline, it's more accurate, as the passed in time could already beyond time.Now() for some wired reason.

petderek · 2017-09-27T20:39:45Z

agent/acs/client/acs_client.go

 	cs := &clientServer{}
 	cs.URL = url
 	cs.CredentialProvider = credentialProvider
 	cs.AgentConfig = cfg
 	cs.ServiceError = &acsError{}
 	cs.RequestHandlers = make(map[string]wsclient.RequestHandler)
 	cs.TypeDecoder = NewACSDecoder()
+	cs.RWTimeout = rwTimeout


nit:
why not just 'timeout'?

I wanted it to convey more meaning that just timeout would convey.

petderek · 2017-09-27T20:41:27Z

agent/acs/handler/acs_handler.go

-		closeErr := client.Close()
-		if closeErr != nil {
-			seelog.Warnf("Error disconnecting: %v", closeErr)
+		if err := client.Close(); err != nil {


There is only one return value.. so is this still more idiomatic than:
if client.Close() != nil {

how is that? I don't see how err := something; if err != nil {} is more idiomatic than if err := something; err != nil {}

Right! I was asking if setting the err variable is necessary at all. On closer inspection I see that we log the error, so you should ignore this :)

petderek · 2017-09-27T20:43:10Z

agent/acs/handler/acs_handler.go

 	return func(interface{}) {
-		seelog.Debug("ACS activity occured")
+		seelog.Debug("ACS activity occurred")


Is this debug line useful?

Yeah, I think so. Shows us when the timer was reset.

petderek · 2017-09-27T20:44:33Z

agent/acs/handler/acs_handler_test.go

-		timer := newDisconnectionTimer(mockWsClient, acsSession.heartbeatTimeout(), acsSession.heartbeatJitter())
-		defer timer.Stop()
-		acsSession.startACSSession(mockWsClient, timer)
+		acsSession.startACSSession(mockWsClient)


nit: remove the function wrapper
go acsSession.startACSSession(mockWsClient)

petderek · 2017-09-27T20:46:43Z

agent/tcs/handler/handler.go

@@ -35,8 +36,8 @@ const (
 	defaultPublishMetricsInterval = 20 * time.Second

 	// The maximum time to wait between heartbeats without disconnecting


Can we go ahead and add the default rwtimeout here too? even if expresed as:

defaultRWTimeout = defaultHeartBeatJitter + defaultHeartbeatTimeout

Yeah, I thought about and didn't think we needed a new const for this. But, I think it makes it more explicit. I'll add that.

jhaynes · 2017-09-27T20:36:53Z

agent/acs/client/acs_client.go

 	"github.com/aws/amazon-ecs-agent/agent/wsclient"
 	"github.com/aws/aws-sdk-go/aws/credentials"
+	"github.com/cihub/seelog"


jhaynes · 2017-09-27T20:40:34Z

agent/acs/handler/acs_handler.go

@@ -377,7 +376,7 @@ func (acsSession *session) heartbeatJitter() time.Duration {

 // createACSClient creates the ACS Client using the specified URL
 func (acsResources *acsSessionResources) createACSClient(url string, cfg *config.Config) wsclient.ClientServer {
-	return acsclient.New(url, cfg, acsResources.credentialsProvider)
+	return acsclient.New(url, cfg, acsResources.credentialsProvider, heartbeatTimeout+heartbeatJitter)


Can you expand on why? I would assume you'd want it to be smaller if anything. That way, you could retry a read/write without necessarily having to re-establish the whole connection.

jhaynes · 2017-09-27T20:44:20Z

agent/acs/handler/acs_handler.go

-		seelog.Debug("ACS activity occured")
+		seelog.Debug("ACS activity occurred")
+		// Reset read deadline as there's activity on the channel
+		if err := client.SetReadDeadline(time.Now().Add(heartbeatTimeout + heartbeatJitter)); err != nil {


Can you explain again here too? Doesn't doubling that have the net effect of doubling your pre-established heartbeatTimeout the first time there is some traffic over the websocket?

jhaynes · 2017-09-27T20:45:34Z

agent/tcs/client/client.go

@@ -46,7 +46,12 @@ type clientServer struct {
 // New returns a client/server to bidirectionally communicate with the backend.
 // The returned struct should have both 'Connect' and 'Serve' called upon it
 // before being used.
-func New(url string, cfg *config.Config, credentialProvider *credentials.Credentials, statsEngine stats.Engine, publishMetricsInterval time.Duration) wsclient.ClientServer {
+func New(url string,
+	cfg *config.Config,


👍 I much prefer this style for functions with more than a few arguments.

jhaynes · 2017-09-27T20:46:08Z

agent/tcs/client/client.go

@@ -67,11 +73,11 @@ func New(url string, cfg *config.Config, credentialProvider *credentials.Credent
 func (cs *clientServer) Serve() error {
 	seelog.Debug("TCS client starting websocket poll loop")
 	if !cs.IsReady() {
-		return fmt.Errorf("Websocket not ready for connections")
+		return fmt.Errorf("tcs client: websocket not ready for connections")


Should TCS be capitalized here? We capitalize ACS in most places.

We're sticking to the style of error strings beginning with a lower case letter.

jhaynes · 2017-09-27T20:47:38Z

agent/tcs/client/client.go

 	}

 	if cs.statsEngine == nil {
-		return fmt.Errorf("uninitialized stats engine")
+		return fmt.Errorf("tcs client: uninitialized stats engine")


As above. Probably should be TCS.

jhaynes · 2017-09-27T20:51:11Z

agent/tcs/handler/handler.go

@@ -35,8 +36,8 @@ const (
 	defaultPublishMetricsInterval = 20 * time.Second

 	// The maximum time to wait between heartbeats without disconnecting
-	defaultHeartbeatTimeout            = 5 * time.Minute
-	defaultHeartbeatJitter             = 3 * time.Minute
+	defaultHeartbeatTimeout            = 1 * time.Minute


I assume this is just meant to mimic the work that @richardpen did for the ACS client.

jhaynes · 2017-09-27T20:52:51Z

agent/tcs/handler/handler.go

@@ -112,7 +118,7 @@ func startSession(url string, cfg *config.Config, credentialProvider *credential
 	timer := time.AfterFunc(utils.AddJitter(heartbeatTimeout, heartbeatJitter), func() {
 		// Close the connection if there haven't been any messages received from backend
 		// for a long time.
-		seelog.Debug("TCS Connection hasn't had a heartbeat or an ack message in too long of a timeout; disconnecting")
+		seelog.Info("TCS Connection hasn't had a heartbeat or an ack message in too long of a timeout; disconnecting")


This wording is confusing. The similar ACS log message is: "ACS Connection hasn't had any activity for too long; closing connection"

I'll modify that.

jhaynes · 2017-09-27T20:53:19Z

agent/tcs/handler/handler.go

+// connection is active
+func anyMessageHandler(client wsclient.ClientServer) func(interface{}) {
+	return func(interface{}) {
+		seelog.Trace("TCS activity occured")


The similar ACS log line is Debug level.

jhaynes · 2017-09-27T20:54:53Z

agent/wsclient/client.go

@@ -48,6 +49,9 @@ const (
 	// wsConnectTimeout specifies the default connection timeout to the backend.
 	wsConnectTimeout = 30 * time.Second

+	// wsHandshakeTimeout specifies the default handshake timeout for the websocket client
+	wsHandshakeTimeout = wsConnectTimeout


I would assume the wsHandshakeTimeout would be <= wsConectTimeout

aaithal · 2017-09-28T00:05:51Z

@samuelkarp @jhaynes @richardpen @petderek I've modified the code to address your comments. Can you please take a look?

richardpen

One minor comment

richardpen · 2017-09-28T17:56:40Z

agent/wsclient/client.go

+
+	// This is just future proofing. Ignore the error as the gorilla websocket
+	// library returns 'nil' anyway for SetWriteDeadline
+	// https://github.com/gorilla/websocket/blob/master/conn.go#L761


It would be good if you could change this link to reference a specific commit, so we won't lose the information if that file is changed. like: https://github.com/gorilla/websocket/blob/4201258b820c74ac8e6922fc9e6b52f71fe46f8d/conn.go#L761

Increase the websocket read and write timeouts as per review comments

aaithal added 2 commits September 27, 2017 10:54

Makefile: fix cni-plugins to build on OSX

9598854

The wc command prefixes spaces to the output, which corrupts the GIT_PORCELAIN variable, thus failing the build. This change removes spaces from the output.

aaithal requested review from samuelkarp, jhaynes, petderek and richardpen September 27, 2017 18:48

CHANGELOG entry for 8703f78 (wsclient: add read write deadlines)

7723038

samuelkarp reviewed Sep 27, 2017

View reviewed changes

richardpen reviewed Sep 27, 2017

View reviewed changes

petderek reviewed Sep 27, 2017

View reviewed changes

jhaynes reviewed Sep 27, 2017

View reviewed changes

aaithal force-pushed the websocketTimeout branch from 9613a31 to 679cf93 Compare September 27, 2017 23:50

samuelkarp approved these changes Sep 28, 2017

View reviewed changes

richardpen approved these changes Sep 28, 2017

View reviewed changes

acs,tcs handlers: increase websocket rw timeout

c140bd3

Increase the websocket read and write timeouts as per review comments

aaithal force-pushed the websocketTimeout branch from 679cf93 to c140bd3 Compare September 28, 2017 20:43

aaithal merged commit b3db90b into aws:dev Sep 28, 2017

aaithal mentioned this pull request Sep 28, 2017

ECS Agent Disconnected becoming more common #985

Closed

jhaynes mentioned this pull request Sep 30, 2017

V1.14.5 release #999

Merged

		@@ -112,7 +118,7 @@ func startSession(url string, cfg config.Config, credentialProvider credential
		timer := time.AfterFunc(utils.AddJitter(heartbeatTimeout, heartbeatJitter), func() {

		@@ -35,8 +36,8 @@ const (
		defaultPublishMetricsInterval = 20 * time.Second

		// The maximum time to wait between heartbeats without disconnecting

Websocket timeout #993

Websocket timeout #993

Conversation

aaithal commented Sep 27, 2017 • edited Loading

Summary

Implementation details

Testing

Description for the changelog

Licensing

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

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal commented Sep 28, 2017

richardpen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aaithal commented Sep 27, 2017 •

edited

Loading