Add logic for verifying PONGS from server

client/connection.go

@@ -50,6 +50,9 @@ type Conn struct {
 	// Internal counters for flood protection
 	badness  time.Duration
 	lastsent time.Time
+
+	// This is for communicating the pongs we get back from our pings.
+	pongResponses chan string
 }
 
 // Config contains options that can be passed to Client to change the
@@ -90,6 +93,10 @@ type Config struct {
 	// Set to 0 to disable client-side pings.
 	PingFreq time.Duration
 
+	// Number of failed pings that we will ignore before closing down the connection.
+	// Set to 0 to disable verifying pong responses.
+	FailedPings int
+
 	// The duration before a connection timeout is triggered. Defaults to 1m.
 	// Set to 0 to wait indefinitely.
 	Timeout time.Duration
@@ -119,7 +126,8 @@ type Config struct {
 func NewConfig(nick string, args ...string) *Config {
 	cfg := &Config{
 		Me:          &state.Nick{Nick: nick},
-		PingFreq: 3 * time.Minute,
+		PingFreq:    2 * time.Minute,
+		FailedPings: 3,
 		NewNick:     func(s string) string { return s + "_" },
 		Recover:     (*Conn).LogPanic, // in dispatch.go
 		SplitLen:    defaultSplit,
@@ -266,6 +274,7 @@ func (conn *Conn) initialise() {
 	conn.in = make(chan *Line, 32)
 	conn.out = make(chan string, 32)
 	conn.die = make(chan struct{})
+	conn.pongResponses = make(chan string)
 	if conn.st != nil {
 		conn.st.Wipe()
 	}
@@ -440,14 +449,51 @@ func (conn *Conn) recv() {
 // ping is started as a goroutine after a connection is established, as
 // long as Config.PingFreq >0. It pings the server every PingFreq seconds.
 func (conn *Conn) ping() {
-	defer conn.wg.Done()
 	tick := time.NewTicker(conn.cfg.PingFreq)
+	var sentPings []string
+
 	for {
 		select {
 		case <-tick.C:
-			conn.Ping(fmt.Sprintf("%d", time.Now().UnixNano()))
+			logging.Debug("irc.ping(): Current outstanding pings: %d/%d",
+				len(sentPings), conn.cfg.FailedPings)
+			// If we haven't cleared this by now it's time to bail.
+			if conn.cfg.FailedPings > 0 && len(sentPings) >= conn.cfg.FailedPings {
+				logging.Error("irc.ping(): Failed to recieve %d pings, closing down the connection.",
+					conn.cfg.FailedPings)
+				tick.Stop()
+				conn.wg.Done()
+				conn.Close()
+				return
+			}
+
+			currentPing := fmt.Sprintf("%d", time.Now().UnixNano())
+			sentPings = append(sentPings, currentPing)
+
+			conn.Ping(currentPing)
+		case pong := <-conn.pongResponses:
+			// No need to waste the cycles if we aren't tracking the number of failed pings.
+			if conn.cfg.FailedPings == 0 {
+				continue
+			}
+
+			logging.Debug("irc.ping(): Processing Pong: %s", pong)
+
+			// See if ping matches
+			shouldClear := false
+			for _, sentPing := range sentPings {
+				if strings.Contains(pong, sentPing) {
+					shouldClear = true
+					break
+				}
+			}
+			// We found a matching ping, reset the count!
+			if shouldClear {
+				sentPings = sentPings[:0]
+			}
 		case <-conn.die:
 			// control channel closed, bail out
+			conn.wg.Done()
 			tick.Stop()
 			return
 		}

client/connection_test.go

@@ -390,7 +390,7 @@ func TestPing(t *testing.T) {
 	}
 
 	// Set a low ping frequency for testing.
-	c.cfg.PingFreq = 10 * res
+	c.cfg.PingFreq = 30 * res
 
 	// reader is a helper to do a "non-blocking" read of c.out
 	reader := func() string {
@@ -433,7 +433,7 @@ func TestPing(t *testing.T) {
 
 	// This is a short window in which the ping should happen
 	// This may result in flaky tests; sorry (and file a bug) if so.
-	<-time.After(2 * res)
+	<-time.After(40 * res)
 	if s := reader(); s == "" || !strings.HasPrefix(s, "PING :") {
 		t.Errorf("Line not output after another %s.", 2*res)
 	}
@@ -453,6 +453,57 @@ func TestPing(t *testing.T) {
 	}
 }
 
+func TestPingPassFail(t *testing.T) {
+	// Passing a second value to setUp stops goroutines from starting
+	c, s := setUp(t, false)
+	defer s.tearDown()
+
+	res := time.Millisecond
+
+	// Windows has a timer resolution of 15.625ms by default.
+	// This means the test will be slower on windows, but
+	// should at least stop most of the flakiness...
+	// https://github.com/fluffle/goirc/issues/88
+	if runtime.GOOS == "windows" {
+		res = 15625 * time.Microsecond
+	}
+
+	// Set a low ping frequency for testing.
+	c.cfg.PingFreq = 10 * res
+
+	// reader is a helper to do a "non-blocking" read of c.out
+	reader := func() string {
+		select {
+		case <-time.After(res):
+		case s := <-c.out:
+			return s
+		}
+		return ""
+	}
+
+	// Start ping loop.
+	exited := callCheck(t)
+	// ping() will decrement the WaitGroup, so we must increment it.
+	c.wg.Add(1)
+	go func() {
+		c.ping()
+		exited.call()
+	}()
+
+	for i := 0; i <= 10; i++ {
+		<-time.After(c.cfg.PingFreq + 1)
+		s := reader()
+		if strings.HasPrefix(s, "PING :") {
+			c.pongResponses <- strings.TrimPrefix(s, "PING :")
+		}
+	}
+	exited.assertNotCalled("Exited before pongs stopped.")
+
+	<-time.After(c.cfg.PingFreq * 4)
+
+	exited.assertWasCalled("Didn't exit after pongs stopped.")
+}
+
 func TestRunLoop(t *testing.T) {
 	// Passing a second value to setUp stops goroutines from starting
 	c, s := setUp(t, false)

client/handlers.go

@@ -16,6 +16,7 @@ var intHandlers = map[string]HandlerFunc{
 	CTCP:     (*Conn).h_CTCP,
 	NICK:     (*Conn).h_NICK,
 	PING:     (*Conn).h_PING,
+	PONG:     (*Conn).h_PONG,
 }
 
 func (conn *Conn) addIntHandlers() {
@@ -31,6 +32,17 @@ func (conn *Conn) h_PING(line *Line) {
 	conn.Pong(line.Args[0])
 }
 
+// Send all pongs to the internal tracker
+func (conn *Conn) h_PONG(line *Line) {
+	// Going by the RFC this makes zero sense, but every IRCd I can find implements
+	// it this way.
+	//
+	// PING :12345
+	// :dreamhack.se.quakenet.org PONG dreamhack.se.quakenet.org :12345
+
+	conn.pongResponses <- line.Text()
+}
+
 // Handler for initial registration with server once tcp connection is made.
 func (conn *Conn) h_REGISTER(line *Line) {
 	if conn.cfg.Pass != "" {