Only create Connection object for active TChannel connections #587

prashantv · 2017-02-23T00:47:18Z

Currently, we create a Connection object as soon as we have a TCP
connection, and then we try to add more information (such as remote peer
information) to the logging context after the init handshake. This can
lead to data races since we're modifying the logging context while
other goroutines may be logging messages with the same context.

Instead of using locks for the logging context, instead separate the
handshake phase of connections out of Connection.

Fixes #584

alxn

@prashantv spent over 1 hour on this, can't find any issues so far.

billf

i've read through this three times and don't have any feedback. canaries & crossdock should catch any interop issues.

akshayjshah

Only blocking comment is about removing the exported error. The remainder are nits and questions.

What's our rollout strategy for this change? I'd prefer to deploy it somewhere before we include it in a new release...

akshayjshah · 2017-02-24T19:04:49Z

connection.go

@@ -100,19 +96,11 @@ var (
 	// on a closed connection
 	ErrConnectionClosed = errors.New("connection is closed")

-	// ErrConnectionNotReady is returned when a caller attempts to send a
-	// request through a connection which has not yet been initialized
-	ErrConnectionNotReady = errors.New("connection is not yet ready")


Removing this is technically a breaking change. Can we keep it and just document that it's now unused?

Yep, good point.

akshayjshah · 2017-02-24T19:07:28Z

connection.go

 	opts := ch.connectionOptions.withDefaults()

 	connID := _nextConnID.Inc()
 	log := ch.log.WithFields(LogFields{
 		{"connID", connID},
 		{"localAddr", conn.LocalAddr()},
 		{"remoteAddr", conn.RemoteAddr()},
+		{"remoteHostPort", remotePeer.HostPort},


Is there a better name we can choose for this field? To me, remoteHostPort isn't obviously different from remoteAddr.

we could come up with a different name, but this is just a refactoring change, and this was the name of the field previously, so I'd like to avoid any renamings:
https://github.com/uber/tchannel-go/blob/dev/connection.go#L1034

akshayjshah · 2017-02-24T19:10:18Z

peer_test.go

@@ -191,12 +191,12 @@ func TestPeerRemoveClosedConnection(t *testing.T) {

 func TestPeerConnectCancelled(t *testing.T) {
 	WithVerifiedServer(t, nil, func(ch *Channel, hostPort string) {
-		ctx, cancel := NewContext(109 * time.Millisecond)
+		ctx, cancel := NewContext(100 * time.Millisecond)


Assuming that the original 109ms timeout was a typo...

That's what I'm assuming too, I'm pretty sure the test didn't need that extra 9ms!

akshayjshah · 2017-02-24T19:11:38Z

peer_test.go

 		cancel()

 		_, err := ch.Connect(ctx, "10.255.255.1:1")
 		require.Error(t, err, "Connect should fail")
-		assert.EqualError(t, ErrRequestCancelled, err.Error(), "Unknown error")
+		assert.EqualError(t, err, ErrRequestCancelled.Error(), "Unexpected error")


:( I hate this package sometimes.

yep, consistency is too hard :(

akshayjshah · 2017-02-24T19:12:27Z

peer_test.go

-		assert.EqualValues(t, 5, count.Load(),
-			"Expect 5 exchange updates: peer add, init mex, new conn, ping, pong")
+		assert.EqualValues(t, 4, count.Load(),
+			"Expect 5 exchange updates: peer add, new conn, ping, pong")


nit: Update error message to 4.

akshayjshah · 2017-02-24T19:17:40Z

preinit_connection.go

+func (ch *Channel) initError(c net.Conn, connDir connectionDirection, id uint32, err error) error {
+	ch.log.WithFields(
+		LogField{"connectionDirection", connDir},
+		LogField{"error", err.Error()},


ErrField?

Totally forgot that existed, thanks!

akshayjshah · 2017-02-24T19:21:01Z

preinit_connection.go

+func setInitDeadline(ctx context.Context, c net.Conn) func() {
+	deadline, ok := ctx.Deadline()
+	if !ok {
+		deadline = time.Now().Add(5 * time.Second)


This seems like a very, very long time...

Yeah :( Unfortunately tests start failing with 1 second, and I think the previous code didn't even have a timeout

akshayjshah · 2017-02-24T19:21:48Z

preinit_connection.go

+		deadline = time.Now().Add(5 * time.Second)
+	}
+
+	c.SetDeadline(deadline)


Do we always need to do this, or only if we're in the !ok block?

If we have a deadline in the context, we use that, otherwise we use 5 seconds as a default timeout for inits.

We always want to set a deadline on the connection though to avoid connection exchanges that never end

My bad - I mixed up the context and the connection.

Currently, we create a Connection object as soon as we have a TCP connection, and then we try to add more information (such as remote peer information) to the logging context after the init handshake. This can lead to data races since we're modifying the logging context while other goroutines may be logging messages with the same context. Instead of using locks for the logging context, instead separate the handshake phase of connections out of Connection. Fixes #584

prashantv

Thanks for the thorough reviews everyone.

In terms of rollout strategy, we can cut a canary of our internal proxy with this change (against dev), as well as our test services, and if things look good with those, we can cut the release.

prashantv · 2017-02-24T20:10:27Z

connection.go

@@ -100,19 +96,11 @@ var (
 	// on a closed connection
 	ErrConnectionClosed = errors.New("connection is closed")

-	// ErrConnectionNotReady is returned when a caller attempts to send a
-	// request through a connection which has not yet been initialized
-	ErrConnectionNotReady = errors.New("connection is not yet ready")


Yep, good point.

prashantv · 2017-02-24T20:12:08Z

connection.go

 	opts := ch.connectionOptions.withDefaults()

 	connID := _nextConnID.Inc()
 	log := ch.log.WithFields(LogFields{
 		{"connID", connID},
 		{"localAddr", conn.LocalAddr()},
 		{"remoteAddr", conn.RemoteAddr()},
+		{"remoteHostPort", remotePeer.HostPort},


we could come up with a different name, but this is just a refactoring change, and this was the name of the field previously, so I'd like to avoid any renamings:
https://github.com/uber/tchannel-go/blob/dev/connection.go#L1034

prashantv · 2017-02-24T20:12:42Z

peer_test.go

@@ -191,12 +191,12 @@ func TestPeerRemoveClosedConnection(t *testing.T) {

 func TestPeerConnectCancelled(t *testing.T) {
 	WithVerifiedServer(t, nil, func(ch *Channel, hostPort string) {
-		ctx, cancel := NewContext(109 * time.Millisecond)
+		ctx, cancel := NewContext(100 * time.Millisecond)


That's what I'm assuming too, I'm pretty sure the test didn't need that extra 9ms!

prashantv · 2017-02-24T20:13:12Z

peer_test.go

 		cancel()

 		_, err := ch.Connect(ctx, "10.255.255.1:1")
 		require.Error(t, err, "Connect should fail")
-		assert.EqualError(t, ErrRequestCancelled, err.Error(), "Unknown error")
+		assert.EqualError(t, err, ErrRequestCancelled.Error(), "Unexpected error")


yep, consistency is too hard :(

prashantv · 2017-02-24T20:13:16Z

peer_test.go

-		assert.EqualValues(t, 5, count.Load(),
-			"Expect 5 exchange updates: peer add, init mex, new conn, ping, pong")
+		assert.EqualValues(t, 4, count.Load(),
+			"Expect 5 exchange updates: peer add, new conn, ping, pong")


prashantv · 2017-02-24T20:14:33Z

preinit_connection.go

+func (ch *Channel) initError(c net.Conn, connDir connectionDirection, id uint32, err error) error {
+	ch.log.WithFields(
+		LogField{"connectionDirection", connDir},
+		LogField{"error", err.Error()},


Totally forgot that existed, thanks!

prashantv · 2017-02-24T20:15:04Z

preinit_connection.go

+func setInitDeadline(ctx context.Context, c net.Conn) func() {
+	deadline, ok := ctx.Deadline()
+	if !ok {
+		deadline = time.Now().Add(5 * time.Second)


Yeah :( Unfortunately tests start failing with 1 second, and I think the previous code didn't even have a timeout

prashantv · 2017-02-24T20:15:54Z

preinit_connection.go

+		deadline = time.Now().Add(5 * time.Second)
+	}
+
+	c.SetDeadline(deadline)


If we have a deadline in the context, we use that, otherwise we use 5 seconds as a default timeout for inits.

We always want to set a deadline on the connection though to avoid connection exchanges that never end

akshayjshah · 2017-02-24T20:57:36Z

preinit_connection.go

+		deadline = time.Now().Add(5 * time.Second)
+	}
+
+	c.SetDeadline(deadline)


My bad - I mixed up the context and the connection.

alxn · 2017-02-24T23:31:26Z

👍

As part of #587, we no longer use the connection's `nextMessageID` field for init req messages, and so a new outbound connection would reuse id 1 for the first ping/call.

prashantv requested review from billf, akshayjshah and alxn February 23, 2017 00:47

prashantv force-pushed the pre_conn branch 2 times, most recently from e8cfc7f to a16b9cb Compare February 23, 2017 06:17

alxn reviewed Feb 23, 2017

View reviewed changes

billf approved these changes Feb 24, 2017

View reviewed changes

prashantv force-pushed the pre_conn branch from a16b9cb to 1030886 Compare February 24, 2017 19:15

akshayjshah suggested changes Feb 24, 2017

View reviewed changes

prashantv added 2 commits February 24, 2017 12:17

CR comments

b33e6c8

prashantv force-pushed the pre_conn branch from 1030886 to b33e6c8 Compare February 24, 2017 20:17

prashantv commented Feb 24, 2017

View reviewed changes

akshayjshah approved these changes Feb 24, 2017

View reviewed changes

prashantv merged commit 3abb4c0 into dev Feb 24, 2017

prashantv deleted the pre_conn branch February 24, 2017 23:28

prashantv mentioned this pull request Feb 27, 2017

Handle parallel incoming connection attempts #597

Merged

prashantv mentioned this pull request Feb 27, 2017

Don't reuse id 1 on first call when used for init req. #598

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Only create Connection object for active TChannel connections #587

Only create Connection object for active TChannel connections #587

prashantv commented Feb 23, 2017

alxn left a comment

billf left a comment

akshayjshah left a comment

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

prashantv left a comment

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

prashantv Feb 24, 2017

akshayjshah Feb 24, 2017

alxn commented Feb 24, 2017

Only create Connection object for active TChannel connections #587

Only create Connection object for active TChannel connections #587

Conversation

prashantv commented Feb 23, 2017

alxn left a comment

Choose a reason for hiding this comment

billf left a comment

Choose a reason for hiding this comment

akshayjshah 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

prashantv 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

alxn commented Feb 24, 2017