fix(logspout): Truncate lines too big for a single UDP packet

logspout/logspout.go

@@ -20,6 +20,11 @@ import (
 	"golang.org/x/net/websocket"
 )
 
+const (
+	MAX_UDP_MSG_BYTES = 65507
+	MAX_TCP_MSG_BYTES = 1048576
+)
+
 var debugMode bool
 
 func debug(v ...interface{}) {
@@ -65,32 +70,42 @@ func syslogStreamer(target Target, types []string, logstream chan *Log) {
 			continue
 		}
 		tag, pid, data := getLogParts(logline)
-		var conn net.Conn
+
+		// HACK: Go's syslog package hardcodes the log format, so let's send our own message
+		data = fmt.Sprintf("%s %s[%s]: %s",
+			time.Now().Format(getopt("DATETIME_FORMAT", dtime.DeisDatetimeFormat)),
+			tag,
+			pid,
+			data)
+
 		if strings.EqualFold(target.Protocol, "tcp") {
 			addr, err := net.ResolveTCPAddr("tcp", target.Addr)
 			assert(err, "syslog")
-			tcpconn, err := net.DialTCP("tcp", nil, addr)
+			conn, err := net.DialTCP("tcp", nil, addr)
+			assert(err, "syslog")
+			assert(conn.SetWriteBuffer(MAX_TCP_MSG_BYTES), "syslog")
+			_, err = fmt.Fprintln(conn, data)
 			assert(err, "syslog")
-			assert(tcpconn.SetWriteBuffer(1048576), "syslog")
-			conn = tcpconn
 		} else if strings.EqualFold(target.Protocol, "udp") {
+			// Truncate the message if it's too long to fit in a single UDP packet.
+			// Get the bytes first.  If the string has non-UTF8 chars, the number of
+			// bytes might exceed the number of characters and it would be good to
+			// know that up front.
+			dataBytes := []byte(data)
+			if len(dataBytes) > MAX_UDP_MSG_BYTES {
+				// Truncate the bytes and add ellipses.
+				dataBytes = append(dataBytes[:MAX_UDP_MSG_BYTES-3], "..."...)
+			}
 			addr, err := net.ResolveUDPAddr("udp", target.Addr)
 			assert(err, "syslog")
-			udpconn, err := net.DialUDP("udp", nil, addr)
+			conn, err := net.DialUDP("udp", nil, addr)
+			assert(err, "syslog")
+			assert(conn.SetWriteBuffer(MAX_UDP_MSG_BYTES), "syslog")
+			_, err = conn.Write(dataBytes)
 			assert(err, "syslog")
-			assert(udpconn.SetWriteBuffer(1048576), "syslog")
-			conn = udpconn
 		} else {
 			assert(fmt.Errorf("%s is not a supported protocol, use either udp or tcp", target.Protocol), "syslog")
 		}
-		// HACK: Go's syslog package hardcodes the log format, so let's send our own message
-		_, err := fmt.Fprintf(conn,
-			"%s %s[%s]: %s",
-			time.Now().Format(getopt("DATETIME_FORMAT", dtime.DeisDatetimeFormat)),
-			tag,
-			pid,
-			data)
-		assert(err, "syslog")
 	}
 }
 

tests/apps_test.go

@@ -6,7 +6,9 @@ import (
 	"fmt"
 	"math/rand"
 	"os"
+	"strings"
 	"testing"
+	"time"
 
 	"github.com/deis/deis/tests/utils"
 )
@@ -27,6 +29,9 @@ var (
 )
 
 func randomString(n int) string {
+	// Be sure we've seeded the random number generator, otherwise we could get the same string
+	// every time.
+	rand.Seed(time.Now().UnixNano())
 	var letters = []rune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ")
 	b := make([]rune, n)
 	for i := range b {
@@ -121,9 +126,27 @@ func appsRunTest(t *testing.T, params *utils.DeisTestConfig) {
 	}
 	utils.CheckList(t, cmd, params, "Hello, 世界", false)
 	utils.Execute(t, "apps:run env", params, true, "GIT_SHA")
-	// run a REALLY large command to test https://github.com/deis/deis/issues/2046
+	// Fleet/systemd unit files have a limit of 2048 characters per line or else one encounters
+	// problems parsing the unit.  To verify long log messages are truncated and do not crash
+	// logspout (see https://github.com/deis/deis/issues/2046) we must issue a (relatively) short
+	// command via `deis apps:run` that produces a LONG, but testable (predictable) log message we
+	// can search for in the output of `deis logs`.
+	//
+	// The strategy for achieving this is to generate 1k random characters, then use that with a
+	// command submitted via `deis apps:run` that will echo those 1k bytes 64x (on a single line).
+	// Such a message is long enough to crash logspout if handled improperly and ALSO gives us a
+	// large, distinct, and predictable string we can search for in the logs to assert success (and
+	// assert that the message didn't crash logspout) WITHOUT ever needing to transmit such an
+	// egregiously long command via `deis apps:run`.
 	largeString := randomString(1024)
-	utils.Execute(t, "apps:run echo "+largeString, params, false, largeString)
+	utils.Execute(t, fmt.Sprintf("apps:run \"printf '%s%%.0s' {1..64}\"", largeString), params, false, largeString)
+	// To assert the long message didn't crash logspout AND made it to the logger, we will search
+	// the logs for a fragment of the long message-- specifically 2x the random string we generated.
+	// This will help us ensure the actual log message made it through and not JUST the log message
+	// that states the command being execured via `deis apps:run`.  We want to find the former, not
+	// the latter because the latter is too short a message to have possibly crashed logspout if
+	// mishandled.
+	utils.Execute(t, "logs", params, false, strings.Repeat(largeString, 2))
 	if err := utils.Chdir(".."); err != nil {
 		t.Fatal(err)
 	}