v1.12.0

This lets us actually send messages to clients as they're ready during
setup.

CHANGELOG.md

@@ -1,3 +1,11 @@
+# 1.12.0 (2019-07-06)
+
+* Update dependencies.
+* Send messages during connect immediately rather than only after we've
+  performed our reverse DNS lookup.
+* Stop logging client reads/writes.
+
+
 # 1.11.0 (2019-01-01)
 
 * No longer automatically rehash once a week. I changed my mind about this!

doc/README.dev.md

@@ -1,9 +1,9 @@
 # Releasing
 * Bump values in `version.go`
 * Update `CHANGELOG.md`
-* Commit
+* `git commit -m vx.y.z`
 * `git push`
 * `git tag -a vx.y.z -m vx.y.z`
 * `export GITHUB_TOKEN=tokenhere`
 * `goreleaser`
-* Don't need to push tags I believe, goreleaser does it.
+* Don't need to push tags. goreleaser does it.

go.mod

@@ -1,7 +1,9 @@
 module github.com/horgh/catbox
 
 require (
-	github.com/horgh/config v0.0.0-20190101202014-d9e8eabe6dbb
+	github.com/horgh/config v0.0.0-20190101204049-770bc48a3bdf
-	github.com/horgh/irc v0.0.0-20190101203129-f09ebee6408d
+	github.com/horgh/irc v0.0.0-20190101204118-d089b0b5b5c5
-	github.com/pkg/errors v0.8.0
+	github.com/pkg/errors v0.8.1
+	github.com/stretchr/objx v0.2.0 // indirect
+	github.com/stretchr/testify v1.3.0
 )

go.sum

@@ -1,13 +1,28 @@
+github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
+github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/horgh/config v0.0.0-20180303191532-3d1f920eb228 h1:R302KZFIBabAYgFZ0hgqRTeCF43Lm5rir+UnJYW3idQ=
 github.com/horgh/config v0.0.0-20180303191532-3d1f920eb228/go.mod h1:DSwQKBmwAzGuDhYajjeJshx5PCPCJfSZJXtbV+8/nck=
 github.com/horgh/config v0.0.0-20190101202014-d9e8eabe6dbb h1:u6pj1d0h6XSjJ84iixIMvSZT1fbLC1g4qqkV54EMOfo=
 github.com/horgh/config v0.0.0-20190101202014-d9e8eabe6dbb/go.mod h1:DSwQKBmwAzGuDhYajjeJshx5PCPCJfSZJXtbV+8/nck=
+github.com/horgh/config v0.0.0-20190101204049-770bc48a3bdf h1:/jDikK0Oteboi7/Z6uzan5aQhiqwMwKTIA+5ZooDclk=
+github.com/horgh/config v0.0.0-20190101204049-770bc48a3bdf/go.mod h1:DSwQKBmwAzGuDhYajjeJshx5PCPCJfSZJXtbV+8/nck=
 github.com/horgh/irc v0.0.0-20180101050313-f421bdb90dcc h1:FXH8Jqdcz9BbR94qHrCVGA5FhbcWNC+HpIXYwVgOc2I=
 github.com/horgh/irc v0.0.0-20180101050313-f421bdb90dcc/go.mod h1:UqEB9NVUSZzN4ESuQX3yEvi80Mgg2O4kttl8oU9+nds=
 github.com/horgh/irc v0.0.0-20190101203129-f09ebee6408d h1:ANDjU4bIeLO80xssAxig8qftG6ohyg08IqsIPnKqafg=
 github.com/horgh/irc v0.0.0-20190101203129-f09ebee6408d/go.mod h1:JLhFcwXOnpvhMer1MERfJuFIoJnADayDWe0VkMN3LP4=
+github.com/horgh/irc v0.0.0-20190101204118-d089b0b5b5c5 h1:wndND79llNLTZZW/Xcg9oKMk/NuGMo+pAX+LKg1mZF8=
+github.com/horgh/irc v0.0.0-20190101204118-d089b0b5b5c5/go.mod h1:JLhFcwXOnpvhMer1MERfJuFIoJnADayDWe0VkMN3LP4=
 github.com/pkg/errors v0.8.0 h1:WdK/asTD0HN+q6hsWO3/vpuAkAr+tw6aNJNDFFf0+qw=
 github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I=
+github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/objx v0.2.0/go.mod h1:qt09Ya8vawLte6SNmTgCsAVtYtaKzEcn8ATUoHMkEqE=
+github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0Q=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=

local_client.go

@@ -176,8 +176,6 @@ func (c *LocalClient) readLoop() {
 			break
 		}
 
-		log.Printf("Client %s: Read: %s", c, strings.TrimSuffix(buf, "\r\n"))
-
 		message, err := irc.ParseMessage(buf)
 		if err != nil {
 			c.Catbox.noticeOpers(fmt.Sprintf("Invalid message from client %s: %s", c,
@@ -249,8 +247,6 @@ Loop:
 				c.Catbox.newEvent(Event{Type: DeadClientEvent, Client: c, Error: err})
 				break Loop
 			}
-
-			log.Printf("Client %s: Sent: %s", c, strings.TrimSuffix(buf, "\r\n"))
 		case <-c.Catbox.ShutdownChan:
 			break Loop
 		}

main.go

@@ -633,16 +633,19 @@ func (cb *Catbox) introduceClient(conn net.Conn) {
 
 		client := NewLocalClient(cb, id, conn)
 
-		msgs := []string{
+		cb.WG.Add(1)
-			fmt.Sprintf("*** Processing your connection to %s",
+		go client.writeLoop()
-				cb.Config.ServerName),
+
-		}
+		sendAuthNotice(
+			client,
+			"*** Processing your connection to "+cb.Config.ServerName,
+		)
 
 		if client.isTLS() {
 			tlsVersion, tlsCipherSuite, err := client.getTLSState()
 			if err != nil {
 				log.Printf("Client %s: %s", client, err)
-				_ = conn.Close() // nolint: gosec
+				close(client.WriteChan)
 				return
 			}
 
@@ -656,48 +659,44 @@ func (cb *Catbox) introduceClient(conn net.Conn) {
 						"Your SSL/TLS version is %s. This server requires at least TLS 1.2. Contact %s if this is a problem.",
 						tlsVersion, cb.Config.AdminEmail)})
 				close(client.WriteChan)
-				cb.WG.Add(1)
-				go client.writeLoop()
 				return
 			}
 
-			msgs = append(msgs, fmt.Sprintf("*** Connected with %s (%s)", tlsVersion,
+			sendAuthNotice(
-				tlsCipherSuite))
+				client,
+				fmt.Sprintf("*** Connected with %s (%s)", tlsVersion, tlsCipherSuite),
+			)
 		}
 
-		msgs = append(msgs, "*** Looking up your hostname...")
+		sendAuthNotice(client, "*** Looking up your hostname...")
 
 		hostname := lookupHostname(context.TODO(), client.Conn.IP)
 		if len(hostname) > 0 {
-			msgs = append(msgs, "*** Found your hostname")
+			sendAuthNotice(client, "*** Found your hostname")
 			client.Hostname = hostname
 		} else {
-			msgs = append(msgs, "*** Couldn't look up your hostname")
+			sendAuthNotice(client, "*** Couldn't look up your hostname")
-		}
-
-		for _, msg := range msgs {
-			client.WriteChan <- irc.Message{
-				Command: "NOTICE",
-				Params:  []string{"AUTH", msg},
-			}
 		}
 
 		// Inform the main server goroutine about the client.
+		//
 		// Do this after sending any messages to the client's channel as it is
 		// possible the channel will be closed by the server (such as during
 		// shutdown).
 		cb.newEvent(Event{Type: NewClientEvent, Client: client})
 
-		// Start read goroutine (endlessly read messages from the client) and write
-		// goroutine (endlessly write messages to the client).
 		cb.WG.Add(1)
 		go client.readLoop()
-
-		cb.WG.Add(1)
-		go client.writeLoop()
 	}()
 }
 
+func sendAuthNotice(c *LocalClient, m string) {
+	c.WriteChan <- irc.Message{
+		Command: "NOTICE",
+		Params:  []string{"AUTH", m},
+	}
+}
+
 // Return true if the server is shutting down.
 func (cb *Catbox) isShuttingDown() bool {
 	// No messages get sent to this channel, so if we receive a message on it,

tests/catbox_test.go

@@ -16,6 +16,8 @@ import (
 	"sync"
 	"syscall"
 	"time"
+
+	"github.com/pkg/errors"
 )
 
 // Catbox holds information about a harnessed catbox.
@@ -281,11 +283,14 @@ func (c *Catbox) linkServer(other *Catbox) error {
 		return fmt.Errorf("error writing server conf: %s: %s", serversConf, err)
 	}
 
-	if err := c.Command.Process.Signal(syscall.SIGHUP); err != nil {
+	return c.rehash()
-		return fmt.Errorf("error sending SIGHUP: %s", err)
+}
-	}
 
-	return nil
+func (c *Catbox) rehash() error {
+	return errors.Wrap(
+		c.Command.Process.Signal(syscall.SIGHUP),
+		"error sending SIGHUP",
+	)
 }
 
 func waitForLog(ch <-chan string, re *regexp.Regexp) bool {

tests/mode_test.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/horgh/irc"
+	"github.com/stretchr/testify/require"
 )
 
 // Test that clients get TS when running MODE on a channel they are on.
@@ -15,56 +16,72 @@ import (
 // another server gets the same TS
 func TestMODETS(t *testing.T) {
 	catbox1, err := harnessCatbox("irc1.example.org", "001")
-	if err != nil {
+	require.NoError(t, err, "harness catbox")
-		t.Fatalf("error harnessing catbox: %s", err)
-	}
 	defer catbox1.stop()
 
 	catbox2, err := harnessCatbox("irc2.example.org", "002")
-	if err != nil {
+	require.NoError(t, err, "harness catbox")
-		t.Fatalf("error harnessing catbox: %s", err)
-	}
 	defer catbox2.stop()
 
-	if err := catbox1.linkServer(catbox2); err != nil {
+	err = catbox1.linkServer(catbox2)
-		t.Fatalf("error linking catbox1 to catbox2: %s", err)
+	require.NoError(t, err, "link catbox1 to catbox2")
-	}
+	err = catbox2.linkServer(catbox1)
-	if err := catbox2.linkServer(catbox1); err != nil {
+	require.NoError(t, err, "link catbox2 to catbox1")
-		t.Fatalf("error linking catbox2 to catbox1: %s", err)
-	}
 
+	// Wait until we link.
+	//
+	// Retry rehashing as I observed a failing build where the second server did
+	// not receive the SIGHUP, yet didn't exit. I'm not sure how that can happen
+	// other than perhaps a race in signal.Notify() such that the signal handler
+	// is registered so the HUP gets received but not delivered to the channel.
 	linkRE := regexp.MustCompile(`Established link to irc2\.`)
-	if !waitForLog(catbox1.LogChan, linkRE) {
+	var attempts int
-		t.Fatalf("failed to see servers link")
+	for {
+		if waitForLog(catbox1.LogChan, linkRE) {
+			break
+		}
+		attempts++
+		if attempts >= 5 {
+			require.Fail(t, "failed to link")
+		}
+		require.NoError(t, err, catbox1.rehash(), "rehash catbox1")
+		require.NoError(t, err, catbox2.rehash(), "rehash catbox2")
 	}
 
 	client1 := NewClient("client1", "127.0.0.1", catbox1.Port)
 	recvChan1, sendChan1, _, err := client1.Start()
-	if err != nil {
+	require.NoError(t, err, "start client")
-		t.Fatalf("error starting client: %s", err)
-	}
 	defer client1.Stop()
 
-	if waitForMessage(t, recvChan1, irc.Message{Command: irc.ReplyWelcome},
+	require.NotNil(
-		"welcome from %s", client1.GetNick()) == nil {
+		t,
-		t.Fatalf("client1 did not get welcome")
+		waitForMessage(
-	}
+			t,
+			recvChan1,
+			irc.Message{Command: irc.ReplyWelcome},
+			"welcome from %s",
+			client1.GetNick(),
+		),
+		"client gets welcome",
+	)
 
 	sendChan1 <- irc.Message{
 		Command: "JOIN",
 		Params:  []string{"#test"},
 	}
-	if waitForMessage(
+	require.NotNil(
 		t,
-		recvChan1,
+		waitForMessage(
-		irc.Message{
+			t,
-			Command: "JOIN",
+			recvChan1,
-			Params:  []string{"#test"},
+			irc.Message{
-		},
+				Command: "JOIN",
-		"%s received JOIN #test", client1.GetNick(),
+				Params:  []string{"#test"},
-	) == nil {
+			},
-		t.Fatalf("client1 did not receive JOIN message")
+			"%s received JOIN #test", client1.GetNick(),
-	}
+		),
+		"client gets JOIN message",
+	)
 
 	sendChan1 <- irc.Message{
 		Command: "MODE",
@@ -78,17 +95,13 @@ func TestMODETS(t *testing.T) {
 		},
 		"%s received 329 response after MODE command", client1.GetNick(),
 	)
-	if creationTimeMessage == nil {
+	require.NotNil(t, creationTimeMessage, "client receives 329 response")
-		t.Fatalf("client1 did not receive 329 response")
-	}
 
 	creationTimeString := ""
 	creationTime := time.Time{}
 	if len(creationTimeMessage.Params) >= 3 {
 		ct, err := strconv.ParseInt(creationTimeMessage.Params[2], 10, 64)
-		if err != nil {
+		require.NoError(t, err, "parse 329 response unixtime")
-			t.Fatalf("error parsing 329 response unixtime: %s", err)
-		}
 		creationTimeString = creationTimeMessage.Params[2]
 		creationTime = time.Unix(ct, 0)
 	}
@@ -103,39 +116,49 @@ func TestMODETS(t *testing.T) {
 		},
 	)
 
-	if time.Since(creationTime) > 30*time.Second {
+	require.True(
-		t.Fatalf("channel creation time is too far in the past: %s", creationTime)
+		t,
-	}
+		time.Since(creationTime) <= 30*time.Second,
+		"channel creation time is new enough",
+	)
 
 	// Try a client on the other server and ensure they get the same time.
 
 	client2 := NewClient("client2", "127.0.0.1", catbox2.Port)
 	recvChan2, sendChan2, _, err := client2.Start()
-	if err != nil {
+	require.NoError(t, err, "start client 2")
-		t.Fatalf("error starting client: %s", err)
-	}
 	defer client2.Stop()
 
-	if waitForMessage(t, recvChan2, irc.Message{Command: irc.ReplyWelcome},
+	require.NotNil(
-		"welcome from %s", client2.GetNick()) == nil {
+		t,
-		t.Fatalf("client2 did not get welcome")
+		waitForMessage(
-	}
+			t,
+			recvChan2,
+			irc.Message{Command: irc.ReplyWelcome},
+			"welcome from %s",
+			client2.GetNick(),
+		),
+		"client 2 gets welcome",
+	)
 
 	sendChan2 <- irc.Message{
 		Command: "JOIN",
 		Params:  []string{"#test"},
 	}
-	if waitForMessage(
+	require.NotNil(
 		t,
-		recvChan2,
+		waitForMessage(
-		irc.Message{
+			t,
-			Command: "JOIN",
+			recvChan2,
-			Params:  []string{"#test"},
+			irc.Message{
-		},
+				Command: "JOIN",
-		"%s received JOIN #test", client2.GetNick(),
+				Params:  []string{"#test"},
-	) == nil {
+			},
-		t.Fatalf("client2 did not receive JOIN message")
+			"%s received JOIN #test",
-	}
+			client2.GetNick(),
+		),
+		"client 2 gets JOIN message",
+	)
 
 	sendChan2 <- irc.Message{
 		Command: "MODE",
@@ -149,9 +172,7 @@ func TestMODETS(t *testing.T) {
 		},
 		"%s received 329 response after MODE command", client2.GetNick(),
 	)
-	if creationTimeMessage == nil {
+	require.NotNil(t, creationTimeMessage, "client 2 receives 329 response")
-		t.Fatalf("client2 did not receive 329 response")
-	}
 
 	messageIsEqual(
 		t,

version.go

@@ -2,7 +2,7 @@ package main
 
 // CreatedDate is the date we're built. This would be nice to generate
 // dynamically, but I don't want to complicate the build.
-const CreatedDate = "2019-01-01"
+const CreatedDate = "2019-07-06"
 
 // Version is our version.
-const Version = "catbox-1.11.0"
+const Version = "catbox-1.12.0"