From ad1e00629b57a62abcfad5942e8b4de9c66a7424 Mon Sep 17 00:00:00 2001
From: Shivaram Lingamneni <slingamn@cs.stanford.edu>
Date: Sat, 2 Dec 2017 20:14:28 -0500
Subject: [PATCH] fix a race condition in idle timeouts

squigz on freenode reported an issue where bots were responding to PING
on time, but were occasionally being timed out regardless. This was a race
condition: timeout was detected as idleTime >= it.quitTimeout, but if
the client responded promptly to its PING message and sent no further messages,
but the main loop subsequently slept for longer than expected (i.e., significantly
longer than quitTimeout), this condition would be met through no fault of the
client's.

The fix here is to explicitly track the last time the ping was sent, then test
!lastSeen.After(lastPinged) instead (making use of time.Time's monotonicity).
It is sufficient that the measurement of lastPinged happens-before the PING is sent.
---
 irc/idletimer.go | 19 ++++++++-----------
 1 file changed, 8 insertions(+), 11 deletions(-)

diff --git a/irc/idletimer.go b/irc/idletimer.go
index 209f1a96..74e11fda 100644
--- a/irc/idletimer.go
+++ b/irc/idletimer.go
@@ -38,7 +38,6 @@ type IdleTimer struct {
 
 	// mutable
 	client   *Client
-	state    TimerState
 	lastSeen time.Time
 }
 
@@ -49,7 +48,6 @@ func NewIdleTimer(client *Client) *IdleTimer {
 		idleTimeout:     IdleTimeout,
 		quitTimeout:     QuitTimeout,
 		client:          client,
-		state:           TimerUnregistered,
 	}
 	return &it
 }
@@ -58,17 +56,18 @@ func NewIdleTimer(client *Client) *IdleTimer {
 // it will eventually be stopped.
 func (it *IdleTimer) Start() {
 	it.Lock()
-	it.state = TimerUnregistered
 	it.lastSeen = time.Now()
 	it.Unlock()
 	go it.mainLoop()
 }
 
 func (it *IdleTimer) mainLoop() {
+	state := TimerUnregistered
+	var lastPinged time.Time
+
 	for {
 		it.Lock()
 		client := it.client
-		state := it.state
 		lastSeen := it.lastSeen
 		it.Unlock()
 
@@ -76,7 +75,8 @@ func (it *IdleTimer) mainLoop() {
 			return
 		}
 
-		idleTime := time.Now().Sub(lastSeen)
+		now := time.Now()
+		idleTime := now.Sub(lastSeen)
 		var nextSleep time.Duration
 
 		if state == TimerUnregistered {
@@ -87,8 +87,8 @@ func (it *IdleTimer) mainLoop() {
 				nextSleep = it.registerTimeout - idleTime
 			}
 		} else if state == TimerIdle {
-			if idleTime < it.quitTimeout {
-				// new ping came in after we transitioned to TimerIdle,
+			if lastSeen.After(lastPinged) {
+				// new pong came in after we transitioned to TimerIdle,
 				// transition back to active and process deadlines below
 				state = TimerActive
 			} else {
@@ -100,6 +100,7 @@ func (it *IdleTimer) mainLoop() {
 			nextSleep = it.idleTimeout - idleTime
 			if nextSleep <= 0 {
 				state = TimerIdle
+				lastPinged = now
 				client.Ping()
 				// grant the client at least quitTimeout to respond
 				nextSleep = it.quitTimeout
@@ -113,10 +114,6 @@ func (it *IdleTimer) mainLoop() {
 			return
 		}
 
-		it.Lock()
-		it.state = state
-		it.Unlock()
-
 		time.Sleep(nextSleep)
 	}
 }