use our own context for response times, deal with null bytes in chann…

…el log, better channel log description
nyaruka · Aug 25, 2017 · 1c37a88 · 1c37a88
1 parent e670898
commit 1c37a88
Show file tree

Hide file tree

Showing 28 changed files with 185 additions and 595 deletions.
diff --git a/backends/rapidpro/backend_test.go b/backends/rapidpro/backend_test.go
@@ -21,7 +21,7 @@ import (
 	"github.com/stretchr/testify/suite"
 )
 
-type MsgTestSuite struct {
+type BackendTestSuite struct {
 	suite.Suite
 	b *backend
 }
@@ -45,7 +45,7 @@ func testConfig() *config.Courier {
 	return config
 }
 
-func (ts *MsgTestSuite) SetupSuite() {
+func (ts *BackendTestSuite) SetupSuite() {
 	// turn off logging
 	logrus.SetOutput(ioutil.Discard)
 
@@ -76,11 +76,11 @@ func (ts *MsgTestSuite) SetupSuite() {
 	ts.b.s3Client = &mockS3Client{}
 }
 
-func (ts *MsgTestSuite) TearDownSuite() {
+func (ts *BackendTestSuite) TearDownSuite() {
 	ts.b.Stop()
 }
 
-func (ts *MsgTestSuite) getChannel(cType string, cUUID string) *DBChannel {
+func (ts *BackendTestSuite) getChannel(cType string, cUUID string) *DBChannel {
 	channelUUID, err := courier.NewChannelUUID(cUUID)
 	ts.NoError(err, "error building channel uuid")
 
@@ -91,7 +91,7 @@ func (ts *MsgTestSuite) getChannel(cType string, cUUID string) *DBChannel {
 	return channel.(*DBChannel)
 }
 
-func (ts *MsgTestSuite) TestMsgUnmarshal() {
+func (ts *BackendTestSuite) TestMsgUnmarshal() {
 	msgJSON := `{
 		"status": "P", 
 		"direction": "O", 
@@ -125,7 +125,7 @@ func (ts *MsgTestSuite) TestMsgUnmarshal() {
 	ts.Equal(msg.ExternalID(), "")
 }
 
-func (ts *MsgTestSuite) TestCheckMsgExists() {
+func (ts *BackendTestSuite) TestCheckMsgExists() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 
 	// check with invalid message id
@@ -146,7 +146,7 @@ func (ts *MsgTestSuite) TestCheckMsgExists() {
 	ts.Nil(err)
 }
 
-func (ts *MsgTestSuite) TestContact() {
+func (ts *BackendTestSuite) TestContact() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 	urn := courier.NewTelURNForCountry("12065551518", "US")
 
@@ -180,7 +180,7 @@ func (ts *MsgTestSuite) TestContact() {
 	ts.Equal("a984069d-0008-4d8c-a772-b14a8a6acccc", contact.UUID)
 }
 
-func (ts *MsgTestSuite) TestContactURN() {
+func (ts *BackendTestSuite) TestContactURN() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 	twChannel := ts.getChannel("TW", "dbc126ed-66bc-4e28-b67b-81dc3327c96a")
 	urn := courier.NewTelURNForCountry("12065551515", "US")
@@ -224,7 +224,7 @@ func (ts *MsgTestSuite) TestContactURN() {
 	ts.Equal("jane", tgContactURN.Display.String)
 }
 
-func (ts *MsgTestSuite) TestContactURNPriority() {
+func (ts *BackendTestSuite) TestContactURNPriority() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 	twChannel := ts.getChannel("TW", "dbc126ed-66bc-4e28-b67b-81dc3327c96a")
 	knURN := courier.NewTelURNForCountry("12065551111", "US")
@@ -254,7 +254,7 @@ func (ts *MsgTestSuite) TestContactURNPriority() {
 	ts.Equal(twChannel.ID(), urns[1].ChannelID)
 }
 
-func (ts *MsgTestSuite) TestMsgStatus() {
+func (ts *BackendTestSuite) TestMsgStatus() {
 	channel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 	now := time.Now().In(time.UTC)
 	time.Sleep(2 * time.Millisecond)
@@ -314,12 +314,12 @@ func (ts *MsgTestSuite) TestMsgStatus() {
 	ts.Equal(m.ErrorCount_, 3)
 }
 
-func (ts *MsgTestSuite) TestHealth() {
+func (ts *BackendTestSuite) TestHealth() {
 	// all should be well in test land
 	ts.Equal(ts.b.Health(), "")
 }
 
-func (ts *MsgTestSuite) TestStatus() {
+func (ts *BackendTestSuite) TestStatus() {
 	// our health should just contain the header
 	ts.True(strings.Contains(ts.b.Status(), "Channel"), ts.b.Status())
 
@@ -343,7 +343,7 @@ func (ts *MsgTestSuite) TestStatus() {
 	ts.True(strings.Contains(ts.b.Status(), "1           0         0    10     KN   dbc126ed-66bc-4e28-b67b-81dc3327c95d"), ts.b.Status())
 }
 
-func (ts *MsgTestSuite) TestOutgoingQueue() {
+func (ts *BackendTestSuite) TestOutgoingQueue() {
 	// add one of our outgoing messages to the queue
 	r := ts.b.redisPool.Get()
 	defer r.Close()
@@ -401,7 +401,7 @@ func (ts *MsgTestSuite) TestOutgoingQueue() {
 	ts.False(sent)
 }
 
-func (ts *MsgTestSuite) TestChannel() {
+func (ts *BackendTestSuite) TestChannel() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 
 	ts.Equal("2500", knChannel.Address())
@@ -425,7 +425,17 @@ func (ts *MsgTestSuite) TestChannel() {
 	ts.Equal("missingValue", val)
 }
 
-func (ts *MsgTestSuite) TestWriteAttachment() {
+func (ts *BackendTestSuite) TestChanneLog() {
+	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
+
+	log := courier.NewChannelLog("Message Send Error", knChannel, courier.NilMsgID, "POST", "/null/value", 400,
+		"request with null \x00", "response with null \x00", time.Millisecond, nil)
+
+	err := writeChannelLog(ts.b, log)
+	ts.NoError(err)
+}
+
+func (ts *BackendTestSuite) TestWriteAttachment() {
 	testServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		defer r.Body.Close()
 
@@ -492,7 +502,7 @@ func (ts *MsgTestSuite) TestWriteAttachment() {
 	ts.True(strings.HasSuffix(m.Attachments()[0], ".png"))
 }
 
-func (ts *MsgTestSuite) TestWriteMsg() {
+func (ts *BackendTestSuite) TestWriteMsg() {
 	knChannel := ts.getChannel("KN", "dbc126ed-66bc-4e28-b67b-81dc3327c95d")
 
 	// have to round to microseconds because postgres can't store nanos
@@ -552,10 +562,15 @@ func (ts *MsgTestSuite) TestWriteMsg() {
 	time.Sleep(5 * time.Second)
 	msg3 := ts.b.NewIncomingMsg(knChannel, urn, "test123").(*DBMsg)
 	ts.NotEqual(msg3.UUID(), msg.UUID())
+
+	// msg with null bytes in it, that's fine for a request body
+	msg = ts.b.NewIncomingMsg(knChannel, urn, "test456\x00456").WithExternalID("ext456").(*DBMsg)
+	err = ts.b.WriteMsg(msg)
+	ts.NoError(err)
 }
 
 func TestMsgSuite(t *testing.T) {
-	suite.Run(t, new(MsgTestSuite))
+	suite.Run(t, new(BackendTestSuite))
 }
 
 var invalidConfigTestCases = []struct {

diff --git a/backends/rapidpro/log.go b/backends/rapidpro/log.go
@@ -2,6 +2,7 @@ package rapidpro
 
 import (
 	"fmt"
+	"strings"
 
 	"time"
 
@@ -29,6 +30,10 @@ func writeChannelLog(b *backend, log *courier.ChannelLog) error {
 		log.Response += "\n\nError: " + log.Error
 	}
 
+	// strip null chars from request and response, postgres doesn't like that
+	log.Request = strings.Trim(log.Request, "\x00")
+	log.Response = strings.Trim(log.Request, "\x00")
+
 	_, err := b.db.Exec(insertLogSQL, dbChan.ID(), log.MsgID, description, log.Error != "", log.Method, log.URL,
 		log.Request, log.Response, log.StatusCode, log.CreatedOn, log.Elapsed/time.Millisecond)
 

diff --git a/handlers/africastalking/africastalking.go b/handlers/africastalking/africastalking.go
@@ -152,9 +152,9 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
 	if err != nil {
-		return status, err
+		return status, nil
 	}
 
 	// was this request successful?

diff --git a/handlers/africastalking/africastalking_test.go b/handlers/africastalking/africastalking_test.go
@@ -76,7 +76,6 @@ var defaultSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: `{ "error": "failed" }`, ResponseStatus: 401,
-		Error:      "received non 200 status: 401",
 		PostParams: map[string]string{"message": `Error Message`},
 		SendPrep:   setSendURL},
 }

diff --git a/handlers/blackmyna/blackmyna.go b/handlers/blackmyna/blackmyna.go
@@ -131,9 +131,9 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
 	if err != nil {
-		return status, err
+		return status, nil
 	}
 
 	// get our external id

diff --git a/handlers/blackmyna/blackmyna_test.go b/handlers/blackmyna/blackmyna_test.go
@@ -80,7 +80,6 @@ var defaultSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: `{ "error": "failed" }`, ResponseStatus: 401,
-		Error:      "received non 200 status: 401",
 		PostParams: map[string]string{"message": `Error Message`, "address": "+250788383383", "senderaddress": "2020"},
 		SendPrep:   setSendURL},
 }

diff --git a/handlers/external/external.go b/handlers/external/external.go
@@ -207,12 +207,11 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
-	if err != nil {
-		return status, err
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
+	if err == nil {
+		status.SetStatus(courier.MsgWired)
 	}
 
-	status.SetStatus(courier.MsgWired)
 	return status, nil
 }
 

diff --git a/handlers/external/external_test.go b/handlers/external/external_test.go
@@ -85,7 +85,6 @@ var getSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: "1: Unknown channel", ResponseStatus: 401,
-		Error:     "received non 200 status: 401",
 		URLParams: map[string]string{"text": `Error Message`, "to": "+250788383383"},
 		SendPrep:  setSendURL},
 	{Label: "Send Attachment",
@@ -113,7 +112,6 @@ var postSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: "1: Unknown channel", ResponseStatus: 401,
-		Error:      "received non 200 status: 401",
 		PostParams: map[string]string{"text": `Error Message`, "to": "+250788383383"},
 		SendPrep:   setSendURL},
 	{Label: "Send Attachment",
@@ -141,7 +139,6 @@ var jsonSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: "1: Unknown channel", ResponseStatus: 401,
-		Error:       "received non 200 status: 401",
 		RequestBody: `{ "to":"+250788383383", "text":"Error Message", "from":"2020" }`,
 		SendPrep:    setSendURL},
 	{Label: "Send Attachment",
@@ -169,7 +166,6 @@ var xmlSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: "1: Unknown channel", ResponseStatus: 401,
-		Error:       "received non 200 status: 401",
 		RequestBody: `<msg><to>+250788383383</to><text>Error Message</text><from>2020</from></msg>`,
 		SendPrep:    setSendURL},
 	{Label: "Send Attachment",

diff --git a/handlers/kannel/kannel.go b/handlers/kannel/kannel.go
@@ -205,7 +205,7 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
 	if err == nil {
 		status.SetStatus(courier.MsgWired)
 	}

diff --git a/handlers/shaqodoon/shaqodoon.go b/handlers/shaqodoon/shaqodoon.go
@@ -182,11 +182,9 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 	rr, err := utils.MakeInsecureHTTPRequest(req)
 
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
-	if err != nil {
-		return status, err
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
+	if err == nil {
+		status.SetStatus(courier.MsgWired)
 	}
-
-	status.SetStatus(courier.MsgWired)
 	return status, nil
 }
diff --git a/handlers/shaqodoon/shaqodoon_test.go b/handlers/shaqodoon/shaqodoon_test.go
@@ -66,7 +66,6 @@ var getSendTestCases = []ChannelSendTestCase{
 		Text: "Error Message", URN: "tel:+250788383383",
 		Status:       "E",
 		ResponseBody: "1: Unknown channel", ResponseStatus: 401,
-		Error:     "received non 200 status: 401",
 		URLParams: map[string]string{"msg": `Error Message`, "to": "250788383383"},
 		SendPrep:  setSendURL},
 	{Label: "Send Attachment",

diff --git a/handlers/smscentral/smscentral.go b/handlers/smscentral/smscentral.go
@@ -106,13 +106,13 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
+	status.AddLog(courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err))
 	if err != nil {
 		return status, err
 	}
 
 	if rr.StatusCode/100 != 2 {
-		return status, errors.Errorf("Got non-200 response [%d] from API")
+		return status, errors.Errorf("Got non-200 response [%d] from API", rr.StatusCode)
 	}
 
 	status.SetStatus(courier.MsgWired)

diff --git a/handlers/telegram/telegram.go b/handlers/telegram/telegram.go
@@ -125,7 +125,7 @@ func (h *handler) sendMsgPart(msg courier.Msg, token string, path string, form u
 	rr, err := utils.MakeHTTPRequest(req)
 
 	// build our channel log
-	log := courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err)
+	log := courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err)
 
 	// was this request successful?
 	ok, err := jsonparser.GetBoolean([]byte(rr.Body), "ok")
@@ -212,8 +212,8 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 			status.AddLog(log)
 
 		default:
-			status.AddLog(courier.NewChannelLog(msg.Channel(), msg.ID(), "", "", courier.NilStatusCode,
-				fmt.Errorf("unknown media type: %s", mediaType), "", "", time.Duration(0), time.Now()))
+			status.AddLog(courier.NewChannelLog("Unknown media type: "+mediaType, msg.Channel(), msg.ID(), "", "", courier.NilStatusCode,
+				"", "", time.Duration(0), fmt.Errorf("unknown media type: %s", mediaType)))
 			hasError = true
 		}
 	}

diff --git a/handlers/test.go b/handlers/test.go
@@ -14,7 +14,6 @@ import (
 	_ "github.com/lib/pq" // postgres driver
 	"github.com/nyaruka/courier"
 	"github.com/nyaruka/courier/config"
-	"github.com/pressly/lg"
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 )
@@ -132,8 +131,6 @@ func newServer(backend courier.Backend) courier.Server {
 	// for benchmarks, log to null
 	logger := logrus.New()
 	logger.Out = ioutil.Discard
-	lg.RedirectStdlogOutput(logger)
-	lg.DefaultLogger = logger
 	logrus.SetOutput(ioutil.Discard)
 
 	return courier.NewServerWithLogger(config.NewTest(), backend, logger)

diff --git a/handlers/twilio/twilio.go b/handlers/twilio/twilio.go
@@ -202,11 +202,12 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 
 	// record our status and log
 	status := h.Backend().NewMsgStatusForID(msg.Channel(), msg.ID(), courier.MsgErrored)
-	status.AddLog(courier.NewChannelLogFromRR(msg.Channel(), msg.ID(), rr, err))
+	log := courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err)
+	status.AddLog(log)
 
 	// fail if we received an error
 	if err != nil {
-		return status, err
+		return status, nil
 	}
 
 	// was this request successful?
@@ -216,13 +217,15 @@ func (h *handler) SendMsg(msg courier.Msg) (courier.MsgStatus, error) {
 			status.SetStatus(courier.MsgFailed)
 			h.Backend().StopMsgContact(msg)
 		}
-		return status, errors.Errorf("received error code from twilio '%d'", errorCode)
+		log.WithError("Message Send Error", errors.Errorf("received error code from twilio '%d'", errorCode))
+		return status, nil
 	}
 
 	// grab the external id
 	externalID, err := jsonparser.GetString([]byte(rr.Body), "sid")
 	if err != nil {
-		return status, errors.Errorf("unable to get sid from body")
+		log.WithError("Message Send Error", errors.Errorf("unable to get sid from body"))
+		return status, nil
 	}
 
 	status.SetStatus(courier.MsgWired)