PING a quiet IRC listener client before closing it (closes #155)

serve closed a connection after five minutes with nothing read and never
sent a PING, so a quiet registered client lost its session. It now sends
PING :<server> after pingInterval with nothing read, and closes the
connection when nothing is read within pongDeadline after that. Every
line read starts both waits again. readTimeout is removed.

Unregistered connections are sent the PING too, so a PONG before
registration is now ignored instead of answered with ERR_NOTREGISTERED.

Model: opus-5-5

internal/ircserver/conn.go

@@ -20,7 +20,6 @@ import (
 
 const (
 	maxLineLen      = 512
-	readTimeout     = 5 * time.Minute
 	writeTimeout    = 30 * time.Second
 	killWriteWindow = 2 * time.Second
 	dnsTimeout      = 3 * time.Second
@@ -214,17 +213,31 @@ func resolveHost(ctx context.Context, addr string) string {
 
 // serve is the main loop for a single IRC client connection.
 // Cancelling ctx when it returns stops the relay goroutine.
-func (c *Conn) serve(ctx context.Context) {
+// When nothing has been read for interval the client is sent
+// a PING, and when nothing is read within deadline after that
+// the connection is closed.
+func (c *Conn) serve(
+	ctx context.Context,
+	interval, deadline time.Duration,
+) {
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
 	defer c.cleanup(ctx)
 
+	ping := time.AfterFunc(interval, func() {
+		c.send("PING :" + c.serverSfx)
+	})
+	defer ping.Stop()
+
 	scanner := bufio.NewScanner(c.conn)
 	scanner.Buffer(make([]byte, maxLineLen), maxLineLen)
 
 	for {
+		// Every line read starts both waits again.
+		ping.Reset(interval)
+
 		_ = c.conn.SetReadDeadline(
-			time.Now().Add(readTimeout),
+			time.Now().Add(interval + deadline),
 		)
 
 		if !scanner.Scan() {
@@ -366,7 +379,7 @@ func (c *Conn) handleMessage(
 	msg *Message,
 ) {
 	// Before registration, only NICK, USER, PASS, PING,
-	// QUIT, and CAP are accepted.
+	// PONG, QUIT, and CAP are accepted.
 	if !c.registered {
 		c.handlePreRegistration(ctx, msg)
 
@@ -452,6 +465,10 @@ func (c *Conn) handlePreRegistration(
 	case irc.CmdPing:
 		c.handlePing(msg)
 
+		return
+	case irc.CmdPong:
+		// The answer to serve's PING, which unregistered
+		// clients are sent too.
 		return
 	case irc.CmdQuit:
 		c.handleQuit(msg)

internal/ircserver/export_test.go

@@ -13,13 +13,16 @@ import (
 	"sneak.berlin/go/neoirc/internal/service"
 )
 
-// NewTestServer creates a Server suitable for testing.
+// NewTestServer creates a Server suitable for testing, whose
+// connections use interval and deadline in place of
+// pingInterval and pongDeadline.
 // The caller must call Stop() when finished.
 func NewTestServer(
 	log *slog.Logger,
 	cfg *config.Config,
 	database *db.Database,
 	brk *broker.Broker,
+	interval, deadline time.Duration,
 ) *Server {
 	globs := &globals.Globals{
 		Appname:   "neoirc",
@@ -38,6 +41,9 @@ func NewTestServer(
 		brk:      brk,
 		svc:      svc,
 		conns:    make(map[*Conn]struct{}),
+
+		pingInterval: interval,
+		pongDeadline: deadline,
 	}
 }
 
@@ -56,6 +62,13 @@ func (s *Server) Listener() net.Listener {
 	return s.listener
 }
 
+// PingTimes returns how long the server's connections wait
+// with nothing read before they are sent a PING, and after it
+// before they are closed.
+func (s *Server) PingTimes() (time.Duration, time.Duration) {
+	return s.pingInterval, s.pongDeadline
+}
+
 // KillWriteWindow is how long Disconnect allows each write
 // to a killed victim.
 const KillWriteWindow = killWriteWindow
@@ -64,6 +77,14 @@ const KillWriteWindow = killWriteWindow
 // output queue when no broker notification arrives.
 const PollInterval = pollInterval
 
+// PingInterval is how long the server waits with nothing read
+// from a connection before it sends a PING.
+const PingInterval = pingInterval
+
+// PongDeadline is how long the server waits after the PING
+// for a line before it closes the connection.
+const PongDeadline = pongDeadline
+
 // NewTestConn returns a Conn for nick on tcpConn, without a
 // server, database or service behind it.
 func NewTestConn(

internal/ircserver/server.go

@@ -6,6 +6,7 @@ import (
 	"log/slog"
 	"net"
 	"sync"
+	"time"
 
 	"go.uber.org/fx"
 	"sneak.berlin/go/neoirc/internal/broker"
@@ -38,6 +39,11 @@ type Server struct {
 	mu       sync.Mutex
 	conns    map[*Conn]struct{}
 	cancel   context.CancelFunc
+
+	// pingInterval and pongDeadline are the constants of the
+	// same names, except in tests, which shorten them.
+	pingInterval time.Duration
+	pongDeadline time.Duration
 }
 
 // New creates a new IRC Server and registers its lifecycle
@@ -57,6 +63,9 @@ func New(
 		listener: nil,
 		cancel:   nil,
 		mu:       sync.Mutex{},
+
+		pingInterval: pingInterval,
+		pongDeadline: pongDeadline,
 	}
 
 	listenAddr := params.Config.IRCListenAddr
@@ -153,7 +162,7 @@ func (s *Server) acceptLoop(ctx context.Context) {
 				s.mu.Unlock()
 			}()
 
-			client.serve(ctx)
+			client.serve(ctx, s.pingInterval, s.pongDeadline)
 		}()
 	}
 }

internal/ircserver/server_test.go

@@ -13,10 +13,13 @@ import (
 	"testing"
 	"time"
 
+	"go.uber.org/fx/fxtest"
 	"sneak.berlin/go/neoirc/internal/broker"
 	"sneak.berlin/go/neoirc/internal/config"
 	"sneak.berlin/go/neoirc/internal/db"
+	"sneak.berlin/go/neoirc/internal/globals"
 	"sneak.berlin/go/neoirc/internal/ircserver"
+	"sneak.berlin/go/neoirc/internal/logger"
 
 	_ "modernc.org/sqlite"
 )
@@ -70,6 +73,22 @@ func newTestEnvWithConfig(
 ) *testEnv {
 	t.Helper()
 
+	return newTestEnvWithPingTimes(
+		t, cfg, ircserver.PingInterval, ircserver.PongDeadline,
+	)
+}
+
+// newTestEnvWithPingTimes is newTestEnvWithConfig, except
+// that the server sends a connection a PING after interval
+// with nothing read, and closes it when nothing is read
+// within deadline after that.
+func newTestEnvWithPingTimes(
+	t *testing.T,
+	cfg *config.Config,
+	interval, deadline time.Duration,
+) *testEnv {
+	t.Helper()
+
 	// A random name, so that no other test environment, not
 	// even an earlier run of the same test, can share it.
 	dsn := fmt.Sprintf(
@@ -126,7 +145,9 @@ func newTestEnvWithConfig(
 		&slog.HandlerOptions{Level: slog.LevelError}, //nolint:exhaustruct
 	))
 
-	srv := ircserver.NewTestServer(log, cfg, database, brk)
+	srv := ircserver.NewTestServer(
+		log, cfg, database, brk, interval, deadline,
+	)
 
 	err = srv.Start(addr)
 	if err != nil {
@@ -174,6 +195,34 @@ func (env *testEnv) dial(t *testing.T) *testClient {
 	}
 }
 
+// The ping interval and PONG deadline for
+// newTestEnvWithShortPings. They differ, so that a test can
+// tell them apart; the PONG deadline is how long a test
+// client has to answer a PING.
+const (
+	testPingInterval = time.Second
+	testPongDeadline = 300 * time.Millisecond
+)
+
+// newTestEnvWithShortPings starts an IRC server that uses
+// testPingInterval and testPongDeadline in place of
+// pingInterval and pongDeadline.
+func newTestEnvWithShortPings(t *testing.T) *testEnv {
+	t.Helper()
+
+	return newTestEnvWithPingTimes(
+		t,
+		&config.Config{ServerName: testServerName},
+		testPingInterval, testPongDeadline,
+	)
+}
+
+// isServerPing reports whether line is the PING the test
+// server sends a quiet client.
+func isServerPing(line string) bool {
+	return line == "PING :"+testServerName
+}
+
 // testClient wraps a raw TCP connection with helpers.
 type testClient struct {
 	t       *testing.T
@@ -272,6 +321,24 @@ func (tc *testClient) readUntilClosed() []string {
 	return lines
 }
 
+// readServerPing reads until the PING the test server sends a
+// quiet client, and fails the test if it came sooner than
+// testPingInterval after lastSent, a time just before the
+// client sent its last line.
+func (tc *testClient) readServerPing(lastSent time.Time) {
+	tc.t.Helper()
+
+	tc.readUntil(isServerPing)
+
+	waited := time.Since(lastSent)
+	if waited < testPingInterval {
+		tc.t.Errorf(
+			"PING came %v after the client's last line, want at least %v",
+			waited, testPingInterval,
+		)
+	}
+}
+
 // assertContains checks that at least one line matches the
 // given substring.
 func assertContains(
@@ -388,6 +455,129 @@ func TestPingPong(t *testing.T) {
 	assertContains(t, lines, "PONG", "PONG response")
 }
 
+// TestQuietClientAnsweringPingStaysConnected checks that a
+// registered client that sends nothing is sent a PING once
+// the ping interval has passed since its last line, and stays
+// connected as long as it answers each one, whether with a
+// PONG or with another line.
+func TestQuietClientAnsweringPingStaysConnected(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name   string
+		answer string
+	}{
+		{name: "PONG", answer: "PONG :" + testServerName},
+		{name: "PING of its own", answer: "PING :answer"},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			env := newTestEnvWithShortPings(t)
+			client := env.dial(t)
+
+			lastSent := time.Now()
+
+			client.register("answers")
+
+			// The second PING comes later than a client that
+			// answers none stays connected.
+			for range 2 {
+				client.readServerPing(lastSent)
+
+				lastSent = time.Now()
+
+				client.send(tt.answer)
+			}
+
+			client.sendAndExpect("PING :still here", "still here")
+		})
+	}
+}
+
+// TestQuietClientNotAnsweringPingIsClosed checks that a
+// registered client that does not answer the PING is
+// disconnected once the PONG deadline has passed after it.
+func TestQuietClientNotAnsweringPingIsClosed(t *testing.T) {
+	t.Parallel()
+
+	// latest leaves room for a loaded host, but is sooner than
+	// a read deadline of two ping intervals would close it.
+	const (
+		earliest = testPingInterval + testPongDeadline
+		latest   = 2 * testPingInterval
+	)
+
+	env := newTestEnvWithShortPings(t)
+	client := env.dial(t)
+
+	lastSent := time.Now()
+
+	client.register("silent")
+	client.readServerPing(lastSent)
+	client.readUntilClosed()
+
+	waited := time.Since(lastSent)
+	if waited < earliest || waited >= latest {
+		t.Errorf(
+			"closed %v after the client's last line, want %v to %v",
+			waited, earliest, latest,
+		)
+	}
+}
+
+// TestUnregisteredClientAnswersPing checks that a PONG before
+// registration, the answer to the PING unregistered clients
+// are sent too, gets no ERR_NOTREGISTERED.
+func TestUnregisteredClientAnswersPing(t *testing.T) {
+	t.Parallel()
+
+	env := newTestEnvWithShortPings(t)
+	client := env.dial(t)
+
+	client.readUntil(isServerPing)
+	client.send("PONG :" + testServerName)
+
+	lines := client.sendAndExpect("PING :after", "PONG")
+	assertNotContains(t, lines, " 451 ", "ERR_NOTREGISTERED")
+}
+
+// TestNewPingTimes checks that a server made by New sends a
+// PING after 90 seconds with nothing read, and closes the
+// connection 30 seconds after that, as README.md states.
+func TestNewPingTimes(t *testing.T) {
+	t.Parallel()
+
+	const (
+		wantInterval = 90 * time.Second
+		wantDeadline = 30 * time.Second
+	)
+
+	log, err := logger.New(nil, logger.Params{
+		Globals: &globals.Globals{},
+	})
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// With no IRC_LISTEN_ADDR, New starts no listener and
+	// uses nothing else from its params.
+	srv := ircserver.New(fxtest.NewLifecycle(t), ircserver.Params{
+		Logger: log,
+		Config: &config.Config{},
+	})
+
+	interval, deadline := srv.PingTimes()
+	if interval != wantInterval || deadline != wantDeadline {
+		t.Errorf(
+			"PING after %v and close %v later, want %v and %v",
+			interval, deadline, wantInterval, wantDeadline,
+		)
+	}
+}
+
 // TestIdleCleanupKeepsActiveUser checks that a user who
 // sends commands is kept by the idle cleanup, and a user who
 // sends nothing is not.