Add request_id logging to Gambit

[rapala61]

FEATURE OVERVIEW

User Story

As an O'Doyle member, I should be able to search Gambit logs by request_id.

Why This Matters

It will help troubleshoot requests between systems.

[aaronschachter]

Is this the Blink request_id? If so, this is similar to the ask in #897 for Blink sending over the retry count. I mentioned this in Slack the other day -- ideally each call to logger should include the request_id so we'll be able to filter the full trace for a given request.

[rapala61]

Yes, is the request_id that Blink generates and sends as part of the headers: https://github.com/DoSomething/blink/blob/master/src/web/middleware/generateRequestId.js.

This is what I asked in the gambit chat a few days ago.

[aaronschachter]

@sergii-tkachenko mentioned today that the Blink request ID is sourced from the request ID Heroku generates, e.g.

2017-05-16T22:03:58.521296+00:00 heroku[router]: at=info method=POST path="/v1/chatbot" host=ds-mdata-responder.herokuapp.com **request_id=e1d52592-f81d-4455-ab20-8899cc5e711c** fwd="54.81.134.89" dyno=web.1 connect=1ms service=307ms status=200 bytes=716 protocol=http

We'll still need to make code changes to output it in each logger function call though to view the full trace for the given request_id:

2017-05-16T22:03:58.521296+00:00 heroku[router]: at=info method=POST path="/v1/chatbot" host=ds-mdata-responder.herokuapp.com request_id=e1d52592-f81d-4455-ab20-8899cc5e711c fwd="54.81.134.89" dyno=web.1 connect=1ms service=307ms status=200 bytes=716 protocol=http
2017-05-16T22:03:58.518328+00:00 app[web.1]: info: mobilecommons.profile_update profile:[removed] oip:213849 update:{"gambit_chatbot_response":"Great! Little moments can have a big impact. Complimenting someone can turn their whole day around.\n\nDo this: post encouraging notes in places that can trigger low self-esteem, like school bathrooms.\n\nThen, text START to share a photo of the messages you posted (and you'll be entered to win a $1500 scholarship)! \n\nBonus: Text back a photo of your posted note by 11:59PM tonight and you can enter to win a gift card of your choice! (Winners announced this week). "}
2017-05-16T22:04:41.562777+00:00 app[web.1]: info: Request handled by worker 3
2017-05-16T22:04:41.564653+00:00 app[web.1]: info: v1/chatbot post:{"profile_id":"191854755","incoming_message":"Inspiring others to, \"live, laugh and love.\"","incoming_image_url":""}
2017-05-16T22:04:42.764836+00:00 app[web.1]: info: mobilecommons.profile_update profile:[removed] oip:213849 update:{"gambit_chatbot_response":"Nice job! YOU deserve a Mirror Message for all the notes you hung. \r\n\n\nWe've got you down for 29 messages posted.\n\nHave you posted more? Text MIRROR START "}
2017-05-16T22:04:42.767766+00:00 heroku[router]: at=info method=POST path="/v1/chatbot" host=ds-mdata-responder.herokuapp.com request_id=51af1fd2-eac5-4748-9fce-2d232b111dff fwd="54.81.134.89" dyno=web.1 connect=1ms service=1213ms status=200 bytes=406 protocol=http

[aaronschachter]

@sergii-tkachenko showed off some handy logging tricks with Logstash today. When using a key=value format in the log message, Logstash adds each pair as fields we can filter by.

at=debug application=blink env=production code=success_gambit_proxy_response_200 worker=GambitChatbotMdataProxyWorker request_id=594eb614-41b8-4a67-87ba-977249e29777 response_status=200 response_status_text="OK" {"success":{"code":200,"message":"At DoSomething, we wanted to [truncated]... enter to win a $5000 scholarship)."}}

produces:

We'll need a significant overhaul of all the logger calls to include request_id -- let's switch to this format when we do for easy filtering.

[aaronschachter]

Refs #1010 -- The overhaul described in the last comment could be DRY with a heroku-logger wrapper we introduced in Gambit Conversations in https://github.com/DoSomething/gambit-conversations/pull/228