diff --git a/backends/rapidpro/backend_test.go b/backends/rapidpro/backend_test.go index 55b2e8f56..11182c37b 100644 --- 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 index 64ce8cc58..0c7d67ebb 100644 --- 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 index e60238904..0cff331be 100644 --- 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 index 875cdf07f..a19bb3520 100644 --- 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 index 8c1cad218..f1766207d 100644 --- 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 index 56c7c4395..6134262cd 100644 --- 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 index 00ed0f7f2..851dea628 100644 --- 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 index 8f2c7eed6..47ebbbf44 100644 --- 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: `+250788383383Error Message2020`, SendPrep: setSendURL}, {Label: "Send Attachment", diff --git a/handlers/kannel/kannel.go b/handlers/kannel/kannel.go index d5e435f2d..01cfceb09 100644 --- 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 index 063e04d98..89ebb0939 100644 --- 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 index 930d54848..64586e2f4 100644 --- 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 index 79d1880c6..ccf2bf865 100644 --- 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 index 45cf8f503..48de4a691 100644 --- 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 index 69edc9c5f..a9e0236b5 100644 --- 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 index ed7f0bea2..b3a084aa4 100644 --- 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) diff --git a/handlers/twilio/twilio_test.go b/handlers/twilio/twilio_test.go index 0aac4e9b5..5ff86085e 100644 --- a/handlers/twilio/twilio_test.go +++ b/handlers/twilio/twilio_test.go @@ -84,21 +84,18 @@ var defaultSendTestCases = []ChannelSendTestCase{ Text: "Error Message", URN: "tel:+250788383383", Status: "E", ResponseBody: `{ "error": "out of credits" }`, ResponseStatus: 401, - Error: "received non 200 status: 401", PostParams: map[string]string{"Body": "Error Message", "To": "+250788383383"}, SendPrep: setSendURL}, {Label: "Error Code", Text: "Error Code", URN: "tel:+250788383383", Status: "E", ResponseBody: `{ "error_code": 1001 }`, ResponseStatus: 200, - Error: "received error code from twilio '1001'", PostParams: map[string]string{"Body": "Error Code", "To": "+250788383383"}, SendPrep: setSendURL}, {Label: "Stopped Contact Code", Text: "Stopped Contact", URN: "tel:+250788383383", Status: "F", ResponseBody: `{ "error_code": 21610 }`, ResponseStatus: 200, - Error: "received error code from twilio '21610'", PostParams: map[string]string{"Body": "Stopped Contact", "To": "+250788383383"}, SendPrep: setSendURL, Stopped: true}, @@ -106,7 +103,6 @@ var defaultSendTestCases = []ChannelSendTestCase{ Text: "No SID", URN: "tel:+250788383383", Status: "E", ResponseBody: `{ }`, ResponseStatus: 200, - Error: "unable to get sid from body", PostParams: map[string]string{"Body": "No SID", "To": "+250788383383"}, SendPrep: setSendURL}, {Label: "Send Attachment", diff --git a/handlers/yo/yo.go b/handlers/yo/yo.go index 173c3114b..0b9f973e9 100644 --- a/handlers/yo/yo.go +++ b/handlers/yo/yo.go @@ -146,9 +146,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)) + log := courier.NewChannelLogFromRR("Message Sent", msg.Channel(), msg.ID(), rr).WithError("Message Send Error", err) + status.AddLog(log) + if err != nil { - return status, err + return status, nil } responseQS, err := url.ParseQuery(string(rr.Body)) diff --git a/handlers/yo/yo_test.go b/handlers/yo/yo_test.go index cf70e71d0..b7f5d96a7 100644 --- a/handlers/yo/yo_test.go +++ b/handlers/yo/yo_test.go @@ -83,7 +83,6 @@ var getSendTestCases = []ChannelSendTestCase{ Text: "Error Message", URN: "tel:+250788383383", Status: "E", ResponseBody: "Error", ResponseStatus: 401, - Error: "received non 200 status: 401", URLParams: map[string]string{"sms_content": `Error Message`, "destinations": string("250788383383")}, SendPrep: setSendURL}, {Label: "Send Attachment", diff --git a/librato/librato.go b/librato/librato.go index 21f76c78b..dafe5073a 100644 --- a/librato/librato.go +++ b/librato/librato.go @@ -117,7 +117,7 @@ func (c *Sender) flush(count int) { return } - logrus.WithField("comp", "librato").WithField("count", len(reqPayload.Gauges)).Info("flushed to librato") + logrus.WithField("comp", "librato").WithField("count", len(reqPayload.Gauges)).Debug("flushed to librato") } // Stop stops our sender, callers can use the WaitGroup used during initialization to block for stop diff --git a/log.go b/log.go index b1e20fd05..7e33379ed 100644 --- a/log.go +++ b/log.go @@ -11,8 +11,8 @@ import ( const NilStatusCode int = 417 // NewChannelLog creates a new channel log for the passed in channel, id, and request and response info -func NewChannelLog(channel Channel, msgID MsgID, method string, url string, statusCode int, err error, - request string, response string, elapsed time.Duration, createdOn time.Time) *ChannelLog { +func NewChannelLog(description string, channel Channel, msgID MsgID, method string, url string, statusCode int, + request string, response string, elapsed time.Duration, err error) *ChannelLog { errString := "" if err != nil { @@ -20,55 +20,65 @@ func NewChannelLog(channel Channel, msgID MsgID, method string, url string, stat } return &ChannelLog{ - Channel: channel, - MsgID: msgID, - Method: method, - URL: url, - StatusCode: statusCode, - Error: errString, - Request: request, - Response: response, - CreatedOn: createdOn, - Elapsed: elapsed, + Description: description, + Channel: channel, + MsgID: msgID, + Method: method, + URL: url, + StatusCode: statusCode, + Error: errString, + Request: request, + Response: response, + CreatedOn: time.Now(), + Elapsed: elapsed, } } // NewChannelLogFromRR creates a new channel log for the passed in channel, id, and request/response log -func NewChannelLogFromRR(channel Channel, msgID MsgID, rr *utils.RequestResponse, err error) *ChannelLog { +func NewChannelLogFromRR(description string, channel Channel, msgID MsgID, rr *utils.RequestResponse) *ChannelLog { log := &ChannelLog{ - Channel: channel, - MsgID: msgID, - Method: rr.Method, - URL: rr.URL, - StatusCode: rr.StatusCode, - Request: rr.Request, - Response: rr.Response, - CreatedOn: time.Now(), - Elapsed: rr.Elapsed, + Description: description, + Channel: channel, + MsgID: msgID, + Method: rr.Method, + URL: rr.URL, + StatusCode: rr.StatusCode, + Request: rr.Request, + Response: rr.Response, + CreatedOn: time.Now(), + Elapsed: rr.Elapsed, } + + return log +} + +// WithError augments the passed in ChannelLog with the passed in description and error if error is not nil +func (l *ChannelLog) WithError(description string, err error) *ChannelLog { if err != nil { - log.Error = err.Error() + l.Error = err.Error() + l.Description = description } - return log + return l } func (l *ChannelLog) String() string { - return fmt.Sprintf("%d %s %d\n%s\n%s\n%s", l.StatusCode, l.URL, l.Elapsed, l.Error, l.Request, l.Response) + return fmt.Sprintf("%s: %d %s %d\n%s\n%s\n%s", l.Description, l.StatusCode, l.URL, l.Elapsed, l.Error, l.Request, l.Response) } // ChannelLog represents the log for a msg being received, sent or having its status updated. It includes the HTTP request // and response for the action as well as the channel it was performed on and an option ID of the msg (for some error // cases we may log without a msg id) type ChannelLog struct { - Channel Channel - MsgID MsgID - Method string - URL string - StatusCode int - Error string - Request string - Response string - Elapsed time.Duration - CreatedOn time.Time + Description string + Channel Channel + MsgID MsgID + Method string + URL string + StatusCode int + Error string + Request string + Response string + Elapsed time.Duration + CreatedOn time.Time } diff --git a/responses.go b/responses.go index 5ee7ac01a..86f91400c 100644 --- a/responses.go +++ b/responses.go @@ -7,7 +7,6 @@ import ( "strings" "time" - "github.com/pressly/lg" "github.com/sirupsen/logrus" validator "gopkg.in/go-playground/validator.v9" @@ -24,20 +23,29 @@ func WriteError(w http.ResponseWriter, r *http.Request, err error) error { errors = append(errors, fmt.Sprintf("field '%s' %s", strings.ToLower(vErrs[i].Field()), vErrs[i].Tag())) } } else { - lg.Log(r.Context()).WithError(err).Error() + logrus.WithFields(logrus.Fields{ + "url": r.Context().Value(contextRequestURL), + "elapsed_ms": getElapsedMS(r), + }).WithError(err).Error() } return writeJSONResponse(w, http.StatusBadRequest, &errorResponse{errors}) } // WriteIgnored writes a JSON response for the passed in message -func WriteIgnored(w http.ResponseWriter, r *http.Request, message string) error { - lg.Log(r.Context()).Info("msg ignored") - return writeData(w, http.StatusOK, message, struct{}{}) +func WriteIgnored(w http.ResponseWriter, r *http.Request, details string) error { + logrus.WithFields(logrus.Fields{ + "url": r.Context().Value(contextRequestURL), + "elapsed_ms": getElapsedMS(r), + "details": details, + }).Info("msg ignored") + return writeData(w, http.StatusOK, details, struct{}{}) } // WriteReceiveSuccess writes a JSON response for the passed in msg indicating we handled it func WriteReceiveSuccess(w http.ResponseWriter, r *http.Request, msg Msg) error { - lg.Log(r.Context()).WithFields(logrus.Fields{ + logrus.WithFields(logrus.Fields{ + "url": r.Context().Value(contextRequestURL), + "elapsed_ms": getElapsedMS(r), "channel_uuid": msg.Channel().UUID(), "msg_uuid": msg.UUID(), "msg_id": msg.ID().Int64, @@ -59,11 +67,18 @@ func WriteReceiveSuccess(w http.ResponseWriter, r *http.Request, msg Msg) error // WriteStatusSuccess writes a JSON response for the passed in status update indicating we handled it func WriteStatusSuccess(w http.ResponseWriter, r *http.Request, status MsgStatus) error { + log := logrus.WithFields(logrus.Fields{ + "url": r.Context().Value(contextRequestURL), + "elapsed_ms": getElapsedMS(r), + "channel_uuid": status.ChannelUUID(), + }) + if status.ID() != NilMsgID { - lg.Log(r.Context()).WithField("channel_uuid", status.ChannelUUID()).WithField("msg_id", status.ID().Int64).Info("status updated") + log = log.WithField("msg_id", status.ID().Int64) } else { - lg.Log(r.Context()).WithField("channel_uuid", status.ChannelUUID()).WithField("msg_external_id", status.ExternalID()).Info("status updated") + log = log.WithField("msg_external_id", status.ExternalID()) } + log.Info("status updated") return writeData(w, http.StatusOK, "Status Update Accepted", &statusData{ @@ -74,8 +89,20 @@ func WriteStatusSuccess(w http.ResponseWriter, r *http.Request, status MsgStatus }) } +func getElapsedMS(r *http.Request) float64 { + start := r.Context().Value(contextRequestStart) + if start == nil { + return -1 + } + startTime, isTime := start.(time.Time) + if !isTime { + return -1 + } + return float64(time.Now().Sub(startTime)) / float64(time.Millisecond) +} + type errorResponse struct { - Text []string `json:"errors"` + Errors []string `json:"errors"` } type successResponse struct { diff --git a/server.go b/server.go index a1fbdb0ac..315698b03 100644 --- a/server.go +++ b/server.go @@ -2,6 +2,7 @@ package courier import ( "bytes" + "context" "fmt" "log" "net/http" @@ -18,7 +19,6 @@ import ( "github.com/nyaruka/courier/config" "github.com/nyaruka/courier/librato" "github.com/nyaruka/courier/utils" - "github.com/pressly/lg" "github.com/sirupsen/logrus" ) @@ -50,9 +50,6 @@ type Server interface { func NewServer(config *config.Courier, backend Backend) Server { // create our top level router logger := logrus.New() - lg.RedirectStdlogOutput(logger) - lg.DefaultLogger = logger - return NewServerWithLogger(config, backend, logger) } @@ -64,7 +61,6 @@ func NewServerWithLogger(config *config.Courier, backend Backend, logger *logrus router.Use(middleware.StripSlashes) router.Use(middleware.RequestID) router.Use(middleware.RealIP) - router.Use(lg.RequestLogger(logger)) router.Use(middleware.Recoverer) router.Use(middleware.Timeout(15 * time.Second)) @@ -108,6 +104,8 @@ func (s *server) Start() error { startSpoolFlushers(s) // wire up our main pages + s.router.NotFound(s.handle404) + s.router.MethodNotAllowed(s.handle405) s.router.Get("/", s.handleIndex) s.router.Get("/status", s.handleStatus) @@ -259,7 +257,11 @@ func (s *server) channelFunctionWrapper(handler ChannelHandler, handlerFunc Chan return } - err = handlerFunc(channel, w, r) + // stuff a few things in our context that help with logging + ctx := context.WithValue(r.Context(), contextRequestURL, r.URL.String()) + ctx = context.WithValue(ctx, contextRequestStart, time.Now()) + + err = handlerFunc(channel, w, r.WithContext(ctx)) if err != nil { WriteError(w, r, err) } @@ -294,11 +296,11 @@ func (s *server) channelUpdateStatusWrapper(handler ChannelHandler, handlerFunc // if we don't have any statuses we still want a channel log, create one if len(statuses) == 0 { - logs = append(logs, NewChannelLog(channel, NilMsgID, r.Method, url, ww.Status(), err, string(request), response.String(), duration, start)) + logs = append(logs, NewChannelLog("Status Error", channel, NilMsgID, r.Method, url, ww.Status(), string(request), response.String(), duration, err)) librato.Default.AddGauge(fmt.Sprintf("courier.msg_status_error_%s", channel.ChannelType()), secondDuration) } for _, status := range statuses { - logs = append(logs, NewChannelLog(channel, status.ID(), r.Method, url, ww.Status(), err, string(request), response.String(), duration, start)) + logs = append(logs, NewChannelLog("Status Updated", channel, status.ID(), r.Method, url, ww.Status(), string(request), response.String(), duration, err)) librato.Default.AddGauge(fmt.Sprintf("courier.msg_status_%s", channel.ChannelType()), secondDuration) } @@ -330,6 +332,7 @@ func (s *server) channelReceiveMsgWrapper(handler ChannelHandler, handlerFunc Ch ww.Tee(response) logs := make([]*ChannelLog, 0, 1) + msgs, err := handlerFunc(channel, ww, r) duration := time.Now().Sub(start) secondDuration := float64(duration) / float64(time.Second) @@ -342,13 +345,13 @@ func (s *server) channelReceiveMsgWrapper(handler ChannelHandler, handlerFunc Ch // if no messages were created we still want to log this to the channel, do so if len(msgs) == 0 { - logs = append(logs, NewChannelLog(channel, NilMsgID, r.Method, url, ww.Status(), err, string(request), prependHeaders(response.String(), ww.Status(), w), duration, start)) + logs = append(logs, NewChannelLog("Receive Error", channel, NilMsgID, r.Method, url, ww.Status(), string(request), prependHeaders(response.String(), ww.Status(), w), duration, err)) librato.Default.AddGauge(fmt.Sprintf("courier.msg_receive_error_%s", channel.ChannelType()), secondDuration) } // otherwise, log the request for each message for _, msg := range msgs { - logs = append(logs, NewChannelLog(channel, msg.ID(), r.Method, url, ww.Status(), err, string(request), prependHeaders(response.String(), ww.Status(), w), duration, start)) + logs = append(logs, NewChannelLog("Message Received", channel, msg.ID(), r.Method, url, ww.Status(), string(request), prependHeaders(response.String(), ww.Status(), w), duration, err)) librato.Default.AddGauge(fmt.Sprintf("courier.msg_receive_%s", channel.ChannelType()), secondDuration) } @@ -410,6 +413,24 @@ func (s *server) handleIndex(w http.ResponseWriter, r *http.Request) { w.Write(buf.Bytes()) } +func (s *server) handle404(w http.ResponseWriter, r *http.Request) { + logrus.WithField("url", r.URL.String()).WithField("method", r.Method).WithField("resp_status", "404").Error("not found") + errors := []string{fmt.Sprintf("not found: %s", r.URL.String())} + err := writeJSONResponse(w, http.StatusNotFound, errorResponse{errors}) + if err != nil { + logrus.WithError(err).Error() + } +} + +func (s *server) handle405(w http.ResponseWriter, r *http.Request) { + logrus.WithField("url", r.URL.String()).WithField("method", r.Method).WithField("resp_status", "405").Error("invalid method") + errors := []string{fmt.Sprintf("method not allowed: %s", r.Method)} + err := writeJSONResponse(w, http.StatusMethodNotAllowed, errorResponse{errors}) + if err != nil { + logrus.WithError(err).Error() + } +} + func (s *server) handleStatus(w http.ResponseWriter, r *http.Request) { if s.config.StatusUsername != "" { user, pass, ok := r.BasicAuth() @@ -433,6 +454,14 @@ func (s *server) handleStatus(w http.ResponseWriter, r *http.Request) { w.Write(buf.Bytes()) } +// for use in request.Context +type contextKey int + +const ( + contextRequestURL contextKey = iota + contextRequestStart +) + var splash = ` ____________ _____ ___ ____/_________ ___________(_)____________ diff --git a/vendor/github.com/pressly/lg/LICENSE b/vendor/github.com/pressly/lg/LICENSE deleted file mode 100644 index e228f9fbe..000000000 --- a/vendor/github.com/pressly/lg/LICENSE +++ /dev/null @@ -1,27 +0,0 @@ -Copyright 2016-current lg authors. All rights reserved. - -Redistribution and use in source and binary forms, with or without -modification, are permitted provided that the following conditions are -met: - - * Redistributions of source code must retain the above copyright -notice, this list of conditions and the following disclaimer. - * Redistributions in binary form must reproduce the above -copyright notice, this list of conditions and the following disclaimer -in the documentation and/or other materials provided with the -distribution. - * The names of authors or contributors may NOT be used to endorse or -promote products derived from this software without specific prior -written permission. - -THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS -"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT -LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR -A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT -OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, -SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT -LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, -DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY -THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT -(INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE -OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. diff --git a/vendor/github.com/pressly/lg/README.md b/vendor/github.com/pressly/lg/README.md deleted file mode 100644 index a7ba66c60..000000000 --- a/vendor/github.com/pressly/lg/README.md +++ /dev/null @@ -1,6 +0,0 @@ -# Lg - -The `lg` ("log") package is a `context`-based application logger built on the Logrus package -(https://github.com/sirupsen/logrus). It also includes a HTTP request logging middleware, `lg.RequestLogger`. - -See the [example](_example/main.go) for a sample program. diff --git a/vendor/github.com/pressly/lg/context.go b/vendor/github.com/pressly/lg/context.go deleted file mode 100644 index b93e2527f..000000000 --- a/vendor/github.com/pressly/lg/context.go +++ /dev/null @@ -1,67 +0,0 @@ -package lg - -import ( - "context" - "net/http" - - "github.com/sirupsen/logrus" -) - -var ( - LoggerCtxKey = &contextKey{"Logger"} - LogEntryCtxKey = &contextKey{"LogEntry"} -) - -func WithLoggerContext(parent context.Context, logger *logrus.Logger) context.Context { - return context.WithValue(parent, LoggerCtxKey, logger) -} - -func WithLogEntry(parent context.Context, logEntry *HTTPLoggerEntry) context.Context { - return context.WithValue(parent, LogEntryCtxKey, logEntry) -} - -func Log(ctx context.Context) logrus.FieldLogger { - if entry, ok := ctx.Value(LogEntryCtxKey).(*HTTPLoggerEntry); ok { - return entry.Logger - } - lgr, ok := ctx.Value(LoggerCtxKey).(*logrus.Logger) - if !ok { - panic("lg: logger backend has not been set on the context.") - } - return lgr -} - -func RequestLog(r *http.Request) logrus.FieldLogger { - return Log(r.Context()) -} - -func SetEntryField(ctx context.Context, key string, value interface{}) { - if entry, ok := ctx.Value(LogEntryCtxKey).(*HTTPLoggerEntry); ok { - entry.Logger = entry.Logger.WithField(key, value) - } -} - -func SetEntryFields(ctx context.Context, fields map[string]interface{}) { - if entry, ok := ctx.Value(LogEntryCtxKey).(*HTTPLoggerEntry); ok { - entry.Logger = entry.Logger.WithFields(fields) - } -} - -func SetRequestEntryField(r *http.Request, key string, value interface{}) { - SetEntryField(r.Context(), key, value) -} - -func SetRequestEntryFields(r *http.Request, fields map[string]interface{}) { - SetEntryFields(r.Context(), fields) -} - -// contextKey is a value for use with context.WithValue. It's used as -// a pointer so it fits in an interface{} without allocation. This technique -// for defining context keys was copied from Go 1.7's new use of context in net/http. -type contextKey struct { - name string -} - -func (k *contextKey) String() string { - return "lg context value " + k.name -} diff --git a/vendor/github.com/pressly/lg/lg.go b/vendor/github.com/pressly/lg/lg.go deleted file mode 100644 index e3412d0ab..000000000 --- a/vendor/github.com/pressly/lg/lg.go +++ /dev/null @@ -1,229 +0,0 @@ -package lg - -import ( - "fmt" - "runtime" - - "github.com/sirupsen/logrus" -) - -var ( - DefaultLogger *logrus.Logger - AlertFn func(level logrus.Level, msg string) -) - -func WithField(key string, value interface{}) *logrus.Entry { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - return DefaultLogger.WithField(key, value) -} - -func WithFields(fields logrus.Fields) *logrus.Entry { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - return DefaultLogger.WithFields(fields) -} - -func WithError(err error) *logrus.Entry { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - return DefaultLogger.WithError(err) -} - -func Debugf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Debugf(format, args...) -} - -func Infof(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Infof(format, args...) -} - -func Printf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Printf(format, args...) -} - -func Warnf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Warnf(format, args...) -} - -func Errorf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Errorf(format, args...) -} - -func Alertf(format string, args ...interface{}) { - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.ErrorLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintf(format, args...)) - } - Errorf(format, args...) -} - -func Fatalf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.FatalLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintf(format, args...)) - } - DefaultLogger.Fatalf(format, args...) -} - -func Panicf(format string, args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.PanicLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintf(format, args...)) - } - DefaultLogger.Panicf(format, args...) -} - -func Debug(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Debug(args...) -} - -func Info(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Info(args...) -} - -func Print(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Print(args...) -} - -func Warn(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Warn(args...) -} - -func Error(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Error(args...) -} - -func Alert(args ...interface{}) { - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.ErrorLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprint(args...)) - } - Error(args...) -} - -func Fatal(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.FatalLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprint(args...)) - } - DefaultLogger.Fatal(args...) -} - -func Panic(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.PanicLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprint(args...)) - } - DefaultLogger.Panic(args...) -} - -func Debugln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Debugln(args...) -} - -func Infoln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Infoln(args...) -} - -func Println(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Println(args...) -} - -func Warnln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Warnln(args...) -} - -func Errorln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - DefaultLogger.Errorln(args...) -} - -func Alertln(args ...interface{}) { - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.ErrorLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintln(args...)) - } - Errorln(args...) -} - -func Fatalln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.FatalLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintln(args...)) - } - DefaultLogger.Fatalln(args...) -} - -func Panicln(args ...interface{}) { - if DefaultLogger == nil { - panic("lg: DefaultLogger is nil") - } - if AlertFn != nil { - _, file, line, _ := runtime.Caller(1) - AlertFn(logrus.PanicLevel, fmt.Sprintf("%s:%d ", file, line)+fmt.Sprintln(args...)) - } - DefaultLogger.Panicln(args...) -} diff --git a/vendor/github.com/pressly/lg/middleware.go b/vendor/github.com/pressly/lg/middleware.go deleted file mode 100644 index 762f014b9..000000000 --- a/vendor/github.com/pressly/lg/middleware.go +++ /dev/null @@ -1,129 +0,0 @@ -package lg - -import ( - "fmt" - "net/http" - "runtime/debug" - "time" - - "github.com/go-chi/chi/middleware" - "github.com/sirupsen/logrus" -) - -// RequestLogger is a middleware for the github.com/sirupsen/logrus to log requests. -// It is equipt to handle recovery in case of panics and record the stack trace -// with a panic log-level. -func RequestLogger(logger *logrus.Logger) func(next http.Handler) http.Handler { - httpLogger := &HTTPLogger{logger} - - return func(next http.Handler) http.Handler { - fn := func(w http.ResponseWriter, r *http.Request) { - entry := httpLogger.NewLogEntry(r) - ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) - - t1 := time.Now() - defer func() { - t2 := time.Now() - - // Recover and record stack traces in case of a panic - if rec := recover(); rec != nil { - entry.Panic(rec, debug.Stack()) - http.Error(ww, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - } - - // Log the entry, the request is complete. - entry.Write(ww.Status(), ww.BytesWritten(), t2.Sub(t1)) - }() - - r = r.WithContext(WithLogEntry(r.Context(), entry)) - next.ServeHTTP(ww, r) - } - return http.HandlerFunc(fn) - } -} - -type HTTPLogger struct { - Logger *logrus.Logger -} - -func (l *HTTPLogger) NewLogEntry(r *http.Request) *HTTPLoggerEntry { - entry := &HTTPLoggerEntry{Logger: logrus.NewEntry(l.Logger)} - logFields := logrus.Fields{} - - if reqID := middleware.GetReqID(r.Context()); reqID != "" { - logFields["req_id"] = reqID - } - - scheme := "http" - if r.TLS != nil { - scheme = "https" - } - logFields["http_scheme"] = scheme - logFields["http_proto"] = r.Proto - logFields["http_method"] = r.Method - - logFields["remote_addr"] = r.RemoteAddr - logFields["user_agent"] = r.UserAgent() - - logFields["uri"] = fmt.Sprintf("%s://%s%s", scheme, r.Host, r.RequestURI) - - entry.Logger = entry.Logger.WithFields(logFields) - - entry.Logger.Infoln("request started") - - return entry -} - -type HTTPLoggerEntry struct { - Logger logrus.FieldLogger // field logger interface, created by RequestLogger - Level *logrus.Level // intended log level to write when request finishes -} - -func (l *HTTPLoggerEntry) Write(status, bytes int, elapsed time.Duration) { - l.Logger = l.Logger.WithFields(logrus.Fields{ - "resp_status": status, "resp_bytes_length": bytes, - "resp_elasped_ms": float64(elapsed.Nanoseconds()) / 1000000.0, - }) - - if l.Level == nil { - l.Logger.Infoln("request complete") - } else { - switch *l.Level { - case logrus.DebugLevel: - l.Logger.Debugln("request complete") - case logrus.InfoLevel: - l.Logger.Infoln("request complete") - case logrus.WarnLevel: - l.Logger.Warnln("request complete") - case logrus.ErrorLevel: - l.Logger.Errorln("request complete") - case logrus.FatalLevel: - l.Logger.Fatalln("request complete") - case logrus.PanicLevel: - l.Logger.Errorln("request complete") - } - } -} - -func (l *HTTPLoggerEntry) Panic(rec interface{}, stack []byte) { - l.Logger = l.Logger.WithFields(logrus.Fields{ - "stack": string(stack), - "panic": fmt.Sprintf("%+v", rec), - }) - panicLevel := logrus.PanicLevel - l.Level = &panicLevel -} - -// PrintPanics is a development middleware that preempts the request logger -// and prints a panic message and stack trace to stdout. -func PrintPanics(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - defer func() { - if rec := recover(); rec != nil { - fmt.Printf("\nPANIC: %+v\n", rec) - fmt.Printf("%s\n", debug.Stack()) - } - }() - next.ServeHTTP(w, r) - }) -} diff --git a/vendor/github.com/pressly/lg/redirect.go b/vendor/github.com/pressly/lg/redirect.go deleted file mode 100644 index 430f2a1f5..000000000 --- a/vendor/github.com/pressly/lg/redirect.go +++ /dev/null @@ -1,25 +0,0 @@ -package lg - -import ( - stdlog "log" - - "github.com/sirupsen/logrus" -) - -func RedirectStdlogOutput(logger *logrus.Logger) { - // Redirect standard logger - stdlog.SetOutput(&logRedirectWriter{logger}) - stdlog.SetFlags(0) -} - -// Proxy writer for any packages using the standard log.Println() stuff -type logRedirectWriter struct { - Logger *logrus.Logger -} - -func (l *logRedirectWriter) Write(p []byte) (n int, err error) { - if len(p) > 0 { - l.Logger.Infof("%s", p[:len(p)-1]) - } - return len(p), nil -}