Automatically close connections after an idle timeout #671

orenkislev · 2017-11-27T14:41:11Z

Fixes #616

If IdleCheckInterval is set (default: disabled), each channel will run a goroutine that periodically checks the last activity time on each connection, and disconnects inbound/outbound connections on which the last activity time exceeds MaxIdleTime (default: 3min).

Note that pings do not count as activity.

prashantv · 2017-11-27T18:06:34Z

Thanks for taking this on @orenkislev!

Couple of requests:

Can you break out the logic for updating the last activity time from this PR?
Run make test locally to make sure tests pass locally.

Currently, there's a big race condition in updateLastActivity, as it's called from 2 separate goroutines, and may end up trying to update the same time.Time at the same time, so I think it's causing tests to fail.

orenkislev · 2017-11-29T01:27:26Z

@prashantv PTAL

The FakeTicker is useful for other tests (see #671), so move it out of the health tests into testutils.

prashantv

Looks good, some high level comments:

Let's keep it simple/obvious and have it Start/Stop from one location unless there's a big benefit
Try to avoid sleeping in tests. We've fought pretty hard to make the tchannel tests not flaky, and sleeps end up destabilizing these tests.

prashantv · 2017-11-29T02:50:24Z

idle_sweep.go

+// them from the peer list.
+// NOTE: This struct is not thread-safe on its own. Calls to Start() and Stop()
+// should be guarded by locking ch.mutable
+type IdleSweep struct {


I don't think we have to export this type

prashantv · 2017-11-29T02:51:35Z

idle_sweep.go

+const (
+	// defaultMaxIdleTime is the duration a connection is allowed to remain idle
+	// before it is automatically closed.
+	defaultMaxIdleTime = 3 * time.Minute


do we need a default? can we just force the user to specify a time if they specify a non-zero idle check interval?

prashantv · 2017-11-29T02:51:48Z

idle_sweep.go

+
+	// defaultIdleCheckInterval is the frequency in which the channel checks for
+	// idle connections. (Default: check is disabled)
+	defaultIdleCheckInterval = time.Duration(0)


if the default is 0, is there much advantage in having this constant?

prashantv · 2017-11-29T02:52:22Z

idle_sweep.go

+
+// newIdleSweep starts a poller that checks for idle connections at given
+// intervals.
+func newIdleSweep(ch *Channel, opts *ChannelOptions) *IdleSweep {


if the idle check interval is nil, should we skip creating this?

I find it better to have an object even if it doesn't do anything, than to have to check for nil everywhere. Makes the code cleaner, and less prone to bugs. I don't feel too strongly about it, if you prefer nil checks.

prashantv · 2017-11-29T02:52:53Z

channel.go

 	ch.mutable.Lock()

 	if ch.mutable.l != nil {
 		ch.mutable.l.Close()
 	}

+	// Stop the idle connections timer.
+	ch.mutable.idleSweep.Stop()


close could be called multiple times, is it OK to call Stop multiple times?

IdleSweep.started will be false, so there won't be any side effects of calling Stop() multiple times.

prashantv · 2017-11-29T03:01:17Z

idle_sweep_test.go

+	for _, peer := range rootPeers {
+		in, out := peer.NumConnections()
+
+		ch.Logger().Infof("numConnections IN: %d  OUT: %d", in, out)


do we need these logs?

prashantv · 2017-11-29T03:03:17Z

idle_sweep_test.go

+
+	serverOpts := testutils.NewOpts().
+		SetTimeNow(clock.Now).
+		SetRelayOptionsFn(func(relayOpts *testutils.ChannelOpts) {


do we need the relay options fn? can we just create a new server which doesn't have tehse options by using ts.NewServer, and ignore ts.Server?

the testutils channel logic is pretty complicated, so I'd like to avoid extra logic there if possible.

prashantv · 2017-11-29T03:04:06Z

idle_sweep_test.go

+		// Both server and client now have an active connection. After 3 minutes they
+		// should be cleared out by the idle sweep.
+		clientTicker.Tick()
+		time.Sleep(testutils.Timeout(10 * time.Millisecond))


why do we need sleeps here? if anything we should have a testutils.WaitFor, but I'm strongly against sleeps in tests, they end up being flaky or cause the tests to slow down

I agree, this was a tough one. The call to checkIdleConnections happens in a goroutine and we have no synchronization channel to know when it completed. There is additionally some small delay between disconnecting the client-side until the server-side receives and processes the disconnect, even though they are both happening in localhost.

I changed to use testutils.WaitFor but I'm open to other suggestions.

prashantv · 2017-11-29T03:04:20Z

testutils/ticker.go

+
+package testutils
+
+import (


nit: can simplify to import "time"

Done (in your branch)

prashantv · 2017-11-29T03:05:00Z

health_ext_test.go

@@ -75,7 +46,7 @@ func TestHealthCheckStopBeforeStart(t *testing.T) {
 		})
 		defer cancel()

-		ft := newFakeTicker()
+		ft := testutils.NewFakeTicker()


I've created #674 to move this out separately to reduce noise in this diff (and to add some simple tests to it).

Thank you! I will merge and rebase

prashantv · 2017-11-29T18:17:28Z

idle_sweep.go

+		return
+	}
+
+	if is.maxIdleTime <= time.Duration(0) {


this sort of validation should happen when creating the channel and return an error.

also, no need to type the constant here, you can do if is.maxIdleTime <= 0

let's also add test coverage for this

prashantv · 2017-11-29T18:18:57Z

channel.go

@@ -299,6 +313,9 @@ func (ch *Channel) Serve(l net.Listener) error {
 	mutable.peerInfo.IsEphemeral = false
 	ch.log = ch.log.WithFields(LogField{"hostPort", mutable.peerInfo.HostPort})

+	// Start the idle connection timer.
+	ch.mutable.idleSweep.Start()


Hmm I don't think we allow channels to be reused. Serve ensures the channel state is ChannelClient (which is the initial state), and we don't allow going backwards anywhere.

prashantv · 2017-11-29T18:21:04Z

idle_sweep.go

+		return
+	}
+
+	is.ch.log.Info("Stopping idle connections poller.")


no need for 2 logs here, just "Stopping" is enough, since nothing below blocks.

prashantv · 2017-11-29T18:21:54Z

idle_sweep.go

+
+	for _, conn := range is.ch.mutable.conns {
+		idleTime := now.Sub(conn.getLastActivityTime())
+		if idleTime >= is.maxIdleTime {


optional: can scope the idleTime just to the if,

if idleTime := now.Sub(..); idleTime >= is.maxIdleTime { [...] }

in general I prefer to scope variables to the minimum scope where they're needed

prashantv · 2017-11-29T18:22:35Z

idle_sweep.go

+		}
+	}
+
+	is.ch.mutable.RUnlock()


can you move the RLock and RUnlock right next to the if, we can treat that as a single block.

prashantv · 2017-11-29T18:23:39Z

idle_sweep.go

+
+	for _, conn := range idleConnections {
+		is.ch.log.WithFields(
+			LogField{"remotePeer", conn.remotePeerInfo}).Info("Closing idle inbound connection.")


can we log the last activity time and the idle time here. if we're calculating them again, we might want to double check that it really is idle just in case of a race.

prashantv · 2017-11-29T18:24:57Z

idle_sweep.go

+	for _, conn := range idleConnections {
+		is.ch.log.WithFields(
+			LogField{"remotePeer", conn.remotePeerInfo}).Info("Closing idle inbound connection.")
+		conn.close(LogField{"reason", "Idle connection closed"})


I think when we close a connection, it doesn't immediately get removed from ch.mutable.conns, so we may end up closing multiple times. that should be safe, but just wanted to call that out.

we could instead only close connections that are active here. (suggest here to avoid holding the RLock for too long, and the filter of idle but not active is very unlikely, so probably won't get a benefit from doing it earlier)

prashantv · 2017-11-29T19:14:45Z

channel.go

@@ -218,6 +229,12 @@ func NewChannel(serviceName string, opts *ChannelOptions) (*Channel, error) {
 		LogField{"chID", chID},
 	)

+	if opts.IdleCheckInterval > 0 && opts.MaxIdleTime <= 0 {
+		logger.Warn("To enable automatically removing idle connections, you must " +


this should return an error, no point allowing users to create a channel with invalid config.

Suggest making an unexported function on ChannelOptions that does this,

func (o *ChannelOpts) validateIdleCheck() error { ... }

that way we can just return an error from validation:

if err := opts.validateIdleCheck(); err != nil { return nil, err }

prashantv · 2017-11-29T19:15:31Z

channel.go

+
+	// Start the idle connection timer.
+	ch.mutable.idleSweep = newIdleSweep(ch, opts)
+	ch.mutable.idleSweep.Start()


no point separating the new and start, we can simplify by just having startIdleSweep and then we don't have the double-start problem

prashantv · 2017-11-29T19:16:52Z

idle_sweep.go

+
+// Stop kills the poller checking for idle connections.
+func (is *idleSweep) Stop() {
+	if !is.started {


we can combine started with the stopCh. on start, set stopCh, on Stop, if stopCh == nil, there's nothing running. once we close(is.stopCh), we can set it to nil

EDIT: Your suggestion causes a race condition. I went back to the original implementation with started.

Either you set stopCh to nil after closing it, in which case you have the goroutine trying to select on a nil variable. Or you can set it to nil from the goroutine, but then Stop() might return without stopCh being nil, which might cause a bug if Stop gets called twice.

Ahh, fair enough, let's stick to this implementation. thanks

prashantv · 2017-11-29T19:17:09Z

idle_sweep.go

+
+	// Acquire the read lock and examine which connections are idle.
+	idleConnections := make([]*Connection, 0, 10)
+


let's remove this blank line as well, so the comment is with the block.

prashantv · 2017-11-29T19:17:36Z

idle_sweep.go

+
+		is.ch.log.WithFields(
+			LogField{"remotePeer", conn.remotePeerInfo},
+			LogField{"lastActivityTime", conn.getLastActivityTime()}).Info("Closing idle inbound connection.")


nit: move the Info(..) to the next line so fields are clearly separated from the message.

prashantv · 2017-11-29T19:19:20Z

idle_sweep_test.go

+	return strings.Join(status, ", ")
+}
+
+func waitForZeroConnections(t *testing.T, channels ...*Channel) bool {


we could actually events here:

// OnPeerStatusChanged is an optional callback that receives a notification // whenever the channel establishes a usable connection to a peer, or loses // a connection to a peer. OnPeerStatusChanged func(*Peer)

consider setting up events so we know when there's a connection change rather than waiting in a loop

prashantv

Looks good! I fixed some minor nits (whitespace, using testutils.Timeout).

Once tests pass, I'll squash the commits and update the description to match the PR and land.

Really appreciate the contribution @orenkislev, thank you!

orenkislev requested a review from prashantv November 27, 2017 14:41

orenkislev force-pushed the close_idle_connections branch from 7e76973 to adf77dc Compare November 29, 2017 01:41

prashantv added a commit that referenced this pull request Nov 29, 2017

testutils: Move out fake ticker

c3aa971

The FakeTicker is useful for other tests (see #671), so move it out of the health tests into testutils.

prashantv mentioned this pull request Nov 29, 2017

testutils: Move out fake ticker #674

Merged

prashantv suggested changes Nov 29, 2017

View reviewed changes

Oren Kislev added 2 commits November 29, 2017 18:07

Implementation of idle connection poller

97ad78c

Addressed comments

a3dcce2

orenkislev force-pushed the close_idle_connections branch from adf77dc to a3dcce2 Compare November 29, 2017 17:08

prashantv reviewed Nov 29, 2017

View reviewed changes

Addressed comments

931521e

prashantv reviewed Nov 29, 2017

View reviewed changes

Oren Kislev and others added 6 commits November 29, 2017 21:29

Addressed comments

07759ad

Fixed race condition

d1ed444

Edited the comment on IdleCheckInterval

1acd35a

nit: no need for import group

702e84a

Minor whitespace cleanup

61031dd

Use testutils.Timeout and increase timeout

f46daf0

prashantv approved these changes Nov 29, 2017

View reviewed changes

prashantv merged commit 84e2c11 into dev Nov 30, 2017

prashantv deleted the close_idle_connections branch November 30, 2017 00:58


		// Acquire the read lock and examine which connections are idle.
		idleConnections := make([]*Connection, 0, 10)

Automatically close connections after an idle timeout #671

Automatically close connections after an idle timeout #671

Conversation

orenkislev commented Nov 27, 2017

prashantv commented Nov 27, 2017

orenkislev commented Nov 29, 2017

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

orenkislev Nov 29, 2017 • 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

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

orenkislev Nov 29, 2017 • 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

Choose a reason for hiding this comment

prashantv left a comment

Choose a reason for hiding this comment

orenkislev Nov 29, 2017 •

edited

Loading

orenkislev Nov 29, 2017 •

edited

Loading