goirc/client/connection_test.go

package client

import (
	"bufio"
	"github.com/fluffle/goevent/event"
	"github.com/fluffle/golog/logging"
	"github.com/fluffle/goirc/state"
	gomock "github.com/dsymonds/gomock/gomock"
	"strings"
	"testing"
	"time"
)

type testState struct {
	ctrl *gomock.Controller
	log  *logging.MockLogger
	st   *state.MockStateTracker
	ed   *event.MockEventDispatcher
	nc   *mockNetConn
	c    *Conn
}

func setUp(t *testing.T, start ...bool) (*Conn, *testState) {
	ctrl := gomock.NewController(t)
	st := state.NewMockStateTracker(ctrl)
	r := event.NewRegistry()
	ed := event.NewMockEventDispatcher(ctrl)
	l := logging.NewMockLogger(ctrl)
	nc := MockNetConn(t)
	c := Client("test", "test", "Testing IRC", r, l)

	// We don't want to have to specify s.log.EXPECT().Debug() for all the
	// random crap that gets logged. This mocks it all out nicely.
	ctrl.RecordCall(l, "Debug", gomock.Any(), gomock.Any()).AnyTimes()

	c.ED = ed
	c.ST = st
	c.st = true
	c.sock = nc
	c.Flood = true // Tests can take a while otherwise
	c.Connected = true
	if len(start) == 0 {
		// Hack to allow tests of send, recv, write etc.
		// NOTE: the value of the boolean doesn't matter.
		c.postConnect()
		// Sleep 1ms to allow background routines to start.
		<-time.After(1e6)
	}

	return c, &testState{ctrl, l, st, ed, nc, c}
}

func (s *testState) tearDown() {
	s.ed.EXPECT().Dispatch("disconnected", s.c, &Line{})
	s.st.EXPECT().Wipe()
	s.log.EXPECT().Error("irc.recv(): %s", "EOF")
	s.log.EXPECT().Info("irc.shutdown(): Disconnected from server.")
	s.nc.ExpectNothing()
	s.c.shutdown()
	<-time.After(1e6)
	s.ctrl.Finish()
}

// Practically the same as the above test, but shutdown is called implicitly
// by recv() getting an EOF from the mock connection.
func TestEOF(t *testing.T) {
	c, s := setUp(t)
	// Since we're not using tearDown() here, manually call Finish()
	defer s.ctrl.Finish()

	// Simulate EOF from server
	s.ed.EXPECT().Dispatch("disconnected", c, &Line{})
	s.st.EXPECT().Wipe()
	s.log.EXPECT().Info("irc.shutdown(): Disconnected from server.")
	s.log.EXPECT().Error("irc.recv(): %s", "EOF")
	s.nc.Close()

	// Since things happen in different internal goroutines, we need to wait
	// 1 ms should be enough :-)
	<-time.After(1e6)

	// Verify that the connection no longer thinks it's connected
	if c.Connected {
		t.Errorf("Conn still thinks it's connected to the server.")
	}
}

func TestClientAndStateTracking(t *testing.T) {
	// This doesn't use setUp() as we want to pass in a mock EventRegistry.
	ctrl := gomock.NewController(t)
	r := event.NewMockEventRegistry(ctrl)
	l := logging.NewMockLogger(ctrl)
	st := state.NewMockStateTracker(ctrl)

	for n, _ := range intHandlers {
		// We can't use EXPECT() here as comparisons of functions are
		// no longer valid in Go, which causes reflect.DeepEqual to bail.
		// Instead, ignore the function arg and just ensure that all the
		// handler names are correctly passed to AddHandler.
		ctrl.RecordCall(r, "AddHandler", gomock.Any(), []string{n})
	}
	c := Client("test", "test", "Testing IRC", r, l)

	// Assert some basic things about the initial state of the Conn struct
	if c.ER != r || c.ED != r || c.l != l || c.st != false || c.ST != nil {
		t.Errorf("Conn not correctly initialised with external deps.")
	}
	if c.in == nil || c.out == nil || c.cSend == nil || c.cLoop == nil {
		t.Errorf("Conn control channels not correctly initialised.")
	}
	if c.Me.Nick != "test" || c.Me.Ident != "test" ||
		c.Me.Name != "Testing IRC" || c.Me.Host != "" {
		t.Errorf("Conn.Me not correctly initialised.")
	}

	// OK, while we're here with a mock event registry...
	for n, _ := range stHandlers {
		// See above.
		ctrl.RecordCall(r, "AddHandler", gomock.Any(), []string{n})
	}
	c.EnableStateTracking()

	// We're expecting the untracked me to be replaced by a tracked one.
	if c.Me.Nick != "test" || c.Me.Ident != "test" ||
		c.Me.Name != "Testing IRC" || c.Me.Host != "" {
		t.Errorf("Enabling state tracking did not replace Me correctly.")
	}
	if !c.st || c.ST == nil || c.Me != c.ST.Me() {
		t.Errorf("State tracker not enabled correctly.")
	}

	// Now, shim in the mock state tracker and test disabling state tracking.
	me := c.Me
	c.ST = st
	st.EXPECT().Wipe()
	for n, _ := range stHandlers {
		// See above.
		ctrl.RecordCall(r, "DelHandler", gomock.Any(), []string{n})
	}
	c.DisableStateTracking()
	if c.st || c.ST != nil || c.Me != me {
		t.Errorf("State tracker not disabled correctly.")
	}
	ctrl.Finish()
}

func TestSend(t *testing.T) {
	// Passing a second value to setUp inhibits postConnect()
	c, s := setUp(t, false)
	// We can't use tearDown here, as it will cause a deadlock in shutdown()
	// trying to send kill messages down channels to nonexistent goroutines.
	defer s.ctrl.Finish()

	// ... so we have to do some of it's work here.
	c.io = bufio.NewReadWriter(
		bufio.NewReader(c.sock),
		bufio.NewWriter(c.sock))

	// Assert that before send is running, nothing should be sent to the socket
	// but writes to the buffered channel "out" should not block.
	c.out <- "SENT BEFORE START"
	s.nc.ExpectNothing()

	// We want to test that the a goroutine calling send will exit correctly.
	exited := false
	go func() {
		c.send()
		exited = true
	}()

	// send is now running in the background as if started by postConnect.
	// This should read the line previously buffered in c.out, and write it
	// to the socket connection.
	s.nc.Expect("SENT BEFORE START")

	// Send another line, just to be sure :-)
	c.out <- "SENT AFTER START"
	s.nc.Expect("SENT AFTER START")

	// Now, use the control channel to exit send and kill the goroutine.
	if exited {
		t.Errorf("Exited before signal sent.")
	}
	c.cSend <- true
	// Allow propagation time...
	<-time.After(1e6)
	if !exited {
		t.Errorf("Didn't exit after signal.")
	}
	s.nc.ExpectNothing()

	// Sending more on c.out shouldn't reach the network.
	c.out <- "SENT AFTER END"
	s.nc.ExpectNothing()
}

func TestRecv(t *testing.T) {
	// Passing a second value to setUp inhibits postConnect()
	c, s := setUp(t, false)
	// We can't tearDown here as we need to explicitly test recv exiting.
	// The same shutdown() caveat in TestSend above also applies.
	defer s.ctrl.Finish()

	// ... so we have to do some of it's work here.
	c.io = bufio.NewReadWriter(
		bufio.NewReader(c.sock),
		bufio.NewWriter(c.sock))

	// Send a line before recv is started up, to verify nothing appears on c.in
	s.nc.Send(":irc.server.org 001 test :First test line.")

	// reader is a helper to do a "non-blocking" read of c.in
	reader := func() *Line {
		select {
		case <-time.After(1e6):
		case l := <-c.in:
			return l
		}
		return nil
	}
	if l := reader(); l != nil {
		t.Errorf("Line parsed before recv started.")
	}

	// We want to test that the a goroutine calling recv will exit correctly.
	exited := false
	go func() {
		c.recv()
		exited = true
	}()

	// Strangely, recv() needs some time to start up, but *only* when this test
	// is run standalone with: client/_test/_testmain --test.run TestRecv
	<-time.After(1e6)

	// Now, this should mean that we'll receive our parsed line on c.in
	if l := reader(); l == nil || l.Cmd != "001" {
		t.Errorf("Bad first line received on input channel")
	}

	// Send a second line, just to be sure.
	s.nc.Send(":irc.server.org 002 test :Second test line.")
	if l := reader(); l == nil || l.Cmd != "002" {
		t.Errorf("Bad second line received on input channel.")
	}

	// Test that recv does something useful with a line it can't parse
	// (not that there are many, parseLine is forgiving).
	s.log.EXPECT().Warn("irc.recv(): problems parsing line:\n  %s",
		":textwithnospaces")
	s.nc.Send(":textwithnospaces")
	if l := reader(); l != nil {
		t.Errorf("Bad line still caused receive on input channel.")
	}

	// The only way recv() exits is when the socket closes.
	if exited {
		t.Errorf("Exited before socket close.")
	}
	s.ed.EXPECT().Dispatch("disconnected", c, &Line{})
	s.st.EXPECT().Wipe()
	s.log.EXPECT().Info("irc.shutdown(): Disconnected from server.")
	s.log.EXPECT().Error("irc.recv(): %s", "EOF")
	s.nc.Close()

	// Since send and runloop aren't actually running, we need to empty their
	// channels manually for recv() to be able to call shutdown correctly.
	<-c.cSend
	<-c.cLoop
	<-c.cPing
	// Give things time to shake themselves out...
	<-time.After(1e6)
	if !exited {
		t.Errorf("Didn't exit on socket close.")
	}

	// Since s.nc is closed we can't attempt another send on it...
	if l := reader(); l != nil {
		t.Errorf("Line received on input channel after socket close.")
	}
}

func TestPing(t *testing.T) {
	// Passing a second value to setUp inhibits postConnect()
	c, s := setUp(t, false)
	// We can't use tearDown here, as it will cause a deadlock in shutdown()
	// trying to send kill messages down channels to nonexistent goroutines.
	defer s.ctrl.Finish()

	// Set a low ping frequency for testing.
	// This still increases testing time by a good few seconds :-/
	c.PingFreq = 1

	// reader is a helper to do a "non-blocking" read of c.out
	reader := func() string {
		select {
		case <-time.After(1e6):
		case s := <-c.out:
			return s
		}
		return ""
	}
	if s := reader(); s != "" {
		t.Errorf("Line output before ping started.")
	}

	// Start ping loop.
	exited := false
	go func() {
		c.ping()
		exited = true
	}()

	// The first ping should be after a second,
	// so we don't expect anything now on c.in
	if s := reader(); s != "" {
		t.Errorf("Line output directly after ping started.")
	}

	<-time.After(1e9)
	if s := reader(); s == "" || !strings.HasPrefix(s, "PING :") {
		t.Errorf("Line not output after 1 second.")
	}

	<-time.After(1e7)
	if s := reader(); s != "" {
		t.Errorf("Line output under a second after last ping.")
	}

	<-time.After(1e9)
	if s := reader(); s == "" || !strings.HasPrefix(s, "PING :") {
		t.Errorf("Line not output after another second.")
	}

	// Now kill the ping loop.
	if exited {
		t.Errorf("Exited before signal sent.")
	}

	c.cPing <- true
	<-time.After(1e9)
	if s := reader(); s != "" {
		t.Errorf("Line output after ping stopped.")
	}

	if !exited {
		t.Errorf("Didn't exit after signal.")
	}
}

func TestRunLoop(t *testing.T) {
	// Passing a second value to setUp inhibits postConnect()
	c, s := setUp(t, false)
	// We can't use tearDown here, as it will cause a deadlock in shutdown()
	// trying to send kill messages down channels to nonexistent goroutines.
	defer s.ctrl.Finish()

	// ... so we have to do some of it's work here.
	c.io = bufio.NewReadWriter(
		bufio.NewReader(c.sock),
		bufio.NewWriter(c.sock))

	// NOTE: here we assert that no Dispatch event has been called yet by
	// calling s.ctrl.Finish(). There doesn't appear to be any harm in this.
	l1 := parseLine(":irc.server.org 001 test :First test line.")
	c.in <- l1
	s.ctrl.Finish()

	// We want to test that the a goroutine calling runLoop will exit correctly.
	// Now, we can expect the call to Dispatch to take place as runLoop starts.
	s.ed.EXPECT().Dispatch("001", c, l1)
	exited := false
	go func() {
		c.runLoop()
		exited = true
	}()
	// Here, the opposite seemed to take place, with TestRunLoop failing when
	// run as part of the suite but passing when run on it's own.
	<-time.After(1e6)

	// Send another line, just to be sure :-)
	l2 := parseLine(":irc.server.org 002 test :Second test line.")
	s.ed.EXPECT().Dispatch("002", c, l2)
	c.in <- l2
	// It appears some sleeping is needed after all of these to ensure channel
	// sends occur before the close signal is sent below...
	<-time.After(1e6)

	// Now, use the control channel to exit send and kill the goroutine.
	if exited {
		t.Errorf("Exited before signal sent.")
	}
	c.cLoop <- true
	// Allow propagation time...
	<-time.After(1e6)
	if !exited {
		t.Errorf("Didn't exit after signal.")
	}

	// Sending more on c.in shouldn't dispatch any further events
	c.in <- l1
}

func TestWrite(t *testing.T) {
	// Passing a second value to setUp inhibits postConnect()
	c, s := setUp(t, false)
	// We can't use tearDown here, as it will cause a deadlock in shutdown()
	// trying to send kill messages down channels to nonexistent goroutines.
	defer s.ctrl.Finish()

	// ... so we have to do some of it's work here.
	c.io = bufio.NewReadWriter(
		bufio.NewReader(c.sock),
		bufio.NewWriter(c.sock))

	// Write should just write a line to the socket.
	c.write("yo momma")
	s.nc.Expect("yo momma")

	// Flood control is disabled -- setUp sets c.Flood = true -- so we should
	// not have set c.badness at this point.
	if c.badness != 0 {
		t.Errorf("Flood control used when Flood = true.")
	}

	c.Flood = false
	c.write("she so useless")
	s.nc.Expect("she so useless")

	// The lastsent time should have been updated very recently...
	if time.Now().Sub(c.lastsent) > time.Millisecond {
		t.Errorf("Flood control not used when Flood = false.")
	}

	// Finally, test the error state by closing the socket then writing.
	// This little function makes sure that all the blocking channels that are
	// written to during the course of s.nc.Close() and c.write() are read from
	// again, to prevent deadlocks when these are both called synchronously.
	// XXX: This may well be a horrible hack.
	go func() {
		<-c.cSend
		<-c.cLoop
		<-c.cPing
	}()
	s.nc.Close()

	s.ed.EXPECT().Dispatch("disconnected", c, &Line{})
	s.st.EXPECT().Wipe()
	s.log.EXPECT().Info("irc.shutdown(): Disconnected from server.")
	s.log.EXPECT().Error("irc.send(): %s", "invalid argument")
	c.write("she can't pass unit tests")
}

func TestRateLimit(t *testing.T) {
	c, s := setUp(t)
	defer s.tearDown()

	if c.badness != 0 {
		t.Errorf("Bad initial values for rate limit variables.")
	}

	// We'll be needing this later...
	abs := func(i time.Duration) time.Duration {
		if (i < 0) {
			return -i
		}
		return i
	}

	// Since the changes to the time module, c.lastsent is now a time.Time.
	// It's initialised on client creation to time.Now() which for the purposes
	// of this test was probably around 1.2 ms ago. This is inconvenient.
	// Making it >10s ago effectively clears out the inconsistency, as this
	// makes elapsed > linetime and thus zeros c.badness and resets c.lastsent.
	c.lastsent = time.Now().Add(-10 * time.Second)
	if l := c.rateLimit(60); l != 0 || c.badness != 0 {
		t.Errorf("Rate limit got non-zero badness from long-ago lastsent.")
	}

	// So, time at the nanosecond resolution is a bit of a bitch. Choosing 60
	// characters as the line length means we should be increasing badness by
	// 2.5 seconds minus the delta between the two ratelimit calls. This should
	// be minimal but it's guaranteed that it won't be zero. Use 10us as a fuzz.
	if l := c.rateLimit(60); l != 0 || abs(c.badness - 25*1e8) > 10 * time.Microsecond {
		t.Errorf("Rate limit calculating badness incorrectly.")
	}
	// At this point, we can tip over the badness scale, with a bit of help.
	// 720 chars => +8 seconds of badness => 10.5 seconds => ratelimit
	if l := c.rateLimit(720); l != 8 * time.Second ||
		abs(c.badness - 105*1e8) > 10 * time.Microsecond {
		t.Errorf("Rate limit failed to return correct limiting values.")
		t.Errorf("l=%d, badness=%d", l, c.badness)
	}
}