Stop the slow test packages waiting (closes #263)

The slowest test packages spent their time waiting rather than testing.

db.Params gains an optional PasswordCost (zero means bcrypt.DefaultCost), and the db, ircserver and handlers tests hash at bcrypt.MinCost. A test IRC server's relay checks its queue on broker notification instead of polling. The service and handlers tests build config.Config directly and run in parallel; config exports DefaultTrustedProxies and ParseTrustedProxies for them. Fixed sleeps give way to waits for the event. Production defaults are unchanged.

What still takes time is CPU work under -race or a timeout a test is about.

Model: opus-5-5

internal/ircserver/conn.go

@@ -70,6 +70,10 @@ type Conn struct {
 	closed      bool
 	killed      bool
 
+	// pollInterval is how often the relay checks the client
+	// output queue when no broker notification arrives.
+	pollInterval time.Duration
+
 	// quitReason is the reason in the QUIT that peers are
 	// sent when the connection ends. The client's QUIT
 	// replaces it.
@@ -83,6 +87,7 @@ func newConn(
 	brk *broker.Broker,
 	cfg *config.Config,
 	svc *service.Service,
+	poll time.Duration,
 ) *Conn {
 	host, _, _ := net.SplitHostPort(tcpConn.RemoteAddr().String())
 
@@ -101,6 +106,8 @@ func newConn(
 		serverSfx:  srvName,
 		remoteIP:   host,
 		quitReason: "Connection closed",
+
+		pollInterval: poll,
 	}
 
 	conn.commands = conn.buildCommandMap()

internal/ircserver/export_test.go

@@ -14,16 +14,16 @@ import (
 )
 
 // NewTestServer creates a Server suitable for testing, whose
-// connections use interval and deadline in place of
-// pingInterval and pongDeadline, and resolve in place of
-// resolveHost.
+// connections use interval, deadline and poll in place of
+// pingInterval, pongDeadline and pollInterval, and resolve in
+// place of resolveHost.
 // 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,
+	interval, deadline, poll time.Duration,
 	resolve func(ctx context.Context, addr string) string,
 ) *Server {
 	globs := &globals.Globals{
@@ -46,10 +46,18 @@ func NewTestServer(
 
 		pingInterval: interval,
 		pongDeadline: deadline,
+		pollInterval: poll,
+		stopTimeout:  stopTimeout,
 		resolveHost:  resolve,
 	}
 }
 
+// SetStopTimeout makes Stop wait at most timeout for the
+// connections' cleanup.
+func (s *Server) SetStopTimeout(timeout time.Duration) {
+	s.stopTimeout = timeout
+}
+
 // ResolveHost is the reverse DNS lookup that a server made by
 // New does for each client.
 func ResolveHost(ctx context.Context, addr string) string {
@@ -99,10 +107,6 @@ const PingInterval = pingInterval
 // for a line before it closes the connection.
 const PongDeadline = pongDeadline
 
-// StopTimeout is the longest Stop waits for the connections'
-// cleanup.
-const StopTimeout = stopTimeout
-
 // NewTestConn returns a Conn for nick on tcpConn, without a
 // server, database or service behind it.
 func NewTestConn(
@@ -111,7 +115,7 @@ func NewTestConn(
 	tcpConn net.Conn,
 	nick string,
 ) *Conn {
-	conn := newConn(tcpConn, log, nil, nil, cfg, nil)
+	conn := newConn(tcpConn, log, nil, nil, cfg, nil, pollInterval)
 	conn.nick = nick
 
 	return conn

internal/ircserver/integration_test.go

@@ -3,7 +3,6 @@ package ircserver_test
 import (
 	"strings"
 	"testing"
-	"time"
 
 	"sneak.berlin/go/neoirc/internal/config"
 )
@@ -1508,9 +1507,6 @@ func TestIntegrationThirdClientObserver(t *testing.T) {
 	bob.joinAndDrain("#trio")
 	carol.joinAndDrain("#trio")
 
-	// Drain join notifications.
-	time.Sleep(100 * time.Millisecond)
-
 	// alice sends; both bob and carol should receive.
 	alice.send("PRIVMSG #trio :hello trio")
 

internal/ircserver/relay.go

@@ -17,7 +17,7 @@ import (
 func (c *Conn) relayMessages(ctx context.Context) {
 	// Use a ticker as a fallback; primary wakeup is via
 	// broker notification.
-	ticker := time.NewTicker(pollInterval)
+	ticker := time.NewTicker(c.pollInterval)
 	defer ticker.Stop()
 
 	for {

internal/ircserver/relay_test.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"golang.org/x/crypto/bcrypt"
+	"sneak.berlin/go/neoirc/internal/config"
 	"sneak.berlin/go/neoirc/internal/dbtest"
 	"sneak.berlin/go/neoirc/internal/ircserver"
 	"sneak.berlin/go/neoirc/internal/service"
@@ -58,7 +59,11 @@ func (env *testEnv) queueMessage(
 func TestRelayKeepsOneWaitChannel(t *testing.T) {
 	t.Parallel()
 
-	env := newTestEnv(t)
+	env := newTestEnvWithResolver(
+		t, &config.Config{ServerName: testServerName},
+		ircserver.PingInterval, ircserver.PongDeadline,
+		ircserver.PollInterval, ircserver.ResolveHost,
+	)
 
 	client := env.dial(t)
 	client.register("idle")
@@ -119,6 +124,63 @@ func (env *testEnv) checkOneWaitChannel(
 	}
 }
 
+// TestRelayDeliversAfterFailedRead checks that when the relay
+// cannot read the client output queue, it waits for the next
+// notification, and delivers once the queue can be read again.
+func TestRelayDeliversAfterFailedRead(t *testing.T) {
+	t.Parallel()
+
+	env := newTestEnv(t)
+	client := env.dial(t)
+	client.register("reader")
+
+	sessionID, err := env.database.GetSessionByNick(t.Context(), "reader")
+	if err != nil {
+		t.Fatalf("get session of reader: %v", err)
+	}
+
+	dbtest.Exec(t, env.dbURL,
+		"ALTER TABLE client_queues RENAME TO hidden_queues")
+
+	// Each pass of the relay takes a wait channel and then reads
+	// the queue. Once it holds a channel after the second
+	// notification, the read after the first one has failed.
+	for range 2 {
+		env.waitForWaitChannel(t, sessionID)
+		env.brk.Notify(sessionID)
+	}
+
+	env.waitForWaitChannel(t, sessionID)
+
+	dbtest.Exec(t, env.dbURL,
+		"ALTER TABLE hidden_queues RENAME TO client_queues")
+
+	env.queueMessage(
+		t, "reader", "PRIVMSG", "carol", "reader", []string{"readable"},
+	)
+
+	client.readUntil(func(l string) bool {
+		return strings.Contains(l, "readable")
+	})
+}
+
+// waitForWaitChannel waits until the session sessionID holds a
+// broker wait channel, and fails the test if it does not
+// within testTimeout.
+func (env *testEnv) waitForWaitChannel(t *testing.T, sessionID int64) {
+	t.Helper()
+
+	deadline := time.Now().Add(testTimeout)
+
+	for env.brk.ListenerCount(sessionID) == 0 {
+		if time.Now().After(deadline) {
+			t.Fatal("the relay is not waiting for a notification")
+		}
+
+		time.Sleep(relayCheckStep)
+	}
+}
+
 // TestRelayMultiLineBody checks that each line of a PRIVMSG
 // or NOTICE body sent over the HTTP API reaches an IRC
 // listener user as its own line.

internal/ircserver/server.go

@@ -53,6 +53,11 @@ type Server struct {
 	pingInterval time.Duration
 	pongDeadline time.Duration
 
+	// pollInterval and stopTimeout are the constants of the
+	// same names, except in tests, which change them.
+	pollInterval time.Duration
+	stopTimeout  time.Duration
+
 	// resolveHost is the function of the same name, except in
 	// tests, which replace it with one that blocks.
 	resolveHost func(ctx context.Context, addr string) string
@@ -79,6 +84,8 @@ func New(
 
 		pingInterval: pingInterval,
 		pongDeadline: pongDeadline,
+		pollInterval: pollInterval,
+		stopTimeout:  stopTimeout,
 		resolveHost:  resolveHost,
 	}
 
@@ -154,10 +161,10 @@ func (s *Server) stop() {
 
 	select {
 	case <-done:
-	case <-time.After(stopTimeout):
+	case <-time.After(s.stopTimeout):
 		s.log.Error(
 			"irc connections not cleaned up before stop timeout",
-			"timeout", stopTimeout,
+			"timeout", s.stopTimeout,
 		)
 	}
 }
@@ -181,7 +188,7 @@ func (s *Server) acceptLoop(ctx context.Context) {
 
 		client := newConn(
 			tcpConn, s.log,
-			s.database, s.brk, s.cfg, s.svc,
+			s.database, s.brk, s.cfg, s.svc, s.pollInterval,
 		)
 
 		s.mu.Lock()

internal/ircserver/server_test.go

@@ -18,6 +18,7 @@ import (
 	"time"
 
 	"go.uber.org/fx/fxtest"
+	"golang.org/x/crypto/bcrypt"
 	"sneak.berlin/go/neoirc/internal/broker"
 	"sneak.berlin/go/neoirc/internal/config"
 	"sneak.berlin/go/neoirc/internal/db"
@@ -35,6 +36,12 @@ import (
 // enough for a heavily loaded host.
 const testTimeout = 30 * time.Second
 
+// testPollInterval is how often the relay of a test server
+// checks the client output queue without a broker
+// notification. It is so long that the relay delivers only on
+// notification, and a test fails when one is missing.
+const testPollInterval = time.Hour
+
 // testEnv holds the shared test infrastructure.
 type testEnv struct {
 	dbURL    string
@@ -94,16 +101,19 @@ func newTestEnvWithPingTimes(
 	t.Helper()
 
 	return newTestEnvWithResolver(
-		t, cfg, interval, deadline, ircserver.ResolveHost,
+		t, cfg, interval, deadline, testPollInterval,
+		ircserver.ResolveHost,
 	)
 }
 
 // newTestEnvWithResolver is newTestEnvWithPingTimes, except
-// that the server looks up a client's hostname with resolve.
+// that the relay checks the client output queue every poll
+// without a broker notification, and the server looks up a
+// client's hostname with resolve.
 func newTestEnvWithResolver(
 	t *testing.T,
 	cfg *config.Config,
-	interval, deadline time.Duration,
+	interval, deadline, poll time.Duration,
 	resolve func(ctx context.Context, addr string) string,
 ) *testEnv {
 	t.Helper()
@@ -119,8 +129,9 @@ func newTestEnvWithResolver(
 	}
 
 	database, err := db.New(lifecycle, db.Params{
-		Logger: dbLog,
-		Config: &config.Config{DBURL: dbURL},
+		Logger:       dbLog,
+		Config:       &config.Config{DBURL: dbURL},
+		PasswordCost: bcrypt.MinCost,
 	})
 	if err != nil {
 		t.Fatalf("new database: %v", err)
@@ -137,7 +148,7 @@ func newTestEnvWithResolver(
 	))
 
 	srv := ircserver.NewTestServer(
-		log, cfg, database, brk, interval, deadline, resolve,
+		log, cfg, database, brk, interval, deadline, poll, resolve,
 	)
 
 	// Port 0 makes the system pick a free port. dial reads it
@@ -433,7 +444,8 @@ func TestRegistrationWhileAnotherLookupIsPending(t *testing.T) {
 
 	env := newTestEnvWithResolver(
 		t, &config.Config{ServerName: testServerName},
-		ircserver.PingInterval, ircserver.PongDeadline, resolve,
+		ircserver.PingInterval, ircserver.PongDeadline,
+		testPollInterval, resolve,
 	)
 
 	env.dial(t)
@@ -1064,12 +1076,16 @@ func TestStopEndsSessions(t *testing.T) {
 }
 
 // TestStopReturnsWhileCleanupIsStuck checks that Stop stops
-// waiting for a connection's cleanup after StopTimeout, so a
-// cleanup that cannot finish does not hold up stopping.
+// waiting for a connection's cleanup after its stop timeout,
+// so a cleanup that cannot finish does not hold up stopping.
 func TestStopReturnsWhileCleanupIsStuck(t *testing.T) {
 	t.Parallel()
 
+	const stopTimeout = 100 * time.Millisecond
+
 	env := newTestEnv(t)
+	env.srv.SetStopTimeout(stopTimeout)
+
 	client := env.dial(t)
 
 	client.register("stuck")
@@ -1095,7 +1111,7 @@ func TestStopReturnsWhileCleanupIsStuck(t *testing.T) {
 
 	select {
 	case <-stopped:
-	case <-time.After(ircserver.StopTimeout + testTimeout):
+	case <-time.After(stopTimeout + testTimeout):
 		t.Error("Stop did not return while a cleanup was stuck")
 	}
 
@@ -1147,9 +1163,6 @@ func TestDirectMessage(t *testing.T) {
 	receiver := env.dial(t)
 	receiver.register("dmreceiver")
 
-	// Give relay goroutines time to start.
-	time.Sleep(100 * time.Millisecond)
-
 	sender.send("PRIVMSG dmreceiver :hello privately")
 
 	lines := receiver.readUntil(func(line string) bool {