Emit Heroku-like logs from the Fastboot server

[kzys]

This change adds Heroku-like logs from the Fastboot server, as we discussed in #1811.

[rust-highfive]

r? @jtgeibel

(rust_highfive has picked a reviewer for you, use r? to override)

[carols10cents]

Should I expect to see logs that look like this when running locally with USE_FASTBOOT=1 npm run start:{local, live, etc}? Because I'm not, I'm only seeing:

2019-11-22T18:45:21.694Z 200 OK /policies

It's fine if I'm not supposed to be seeing these logs locally, the extra info isn't really relevant during development, it just surprised me because I didn't see anything in this PR that checked the environment. Probably something I'm missing about how ember and/or fastboot works though.

When I deploy to staging with USE_FASTBOOT set to 1 I see:

2019-11-22T19:08:14.115824+00:00 app[web.1]: (node:27) [DEP0066] DeprecationWarning: OutgoingMessage.prototype._headers is deprecated
2019-11-22T19:08:14.640054+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=bc4486a2-4a2f-465a-a160-95878f1e3c19 fwd="71.112.158.75,70.132.33.80" dyno=web.1 connect=1ms service=579ms status=200 bytes=5834 protocol=https
2019-11-22T19:08:14.621895+00:00 app[web.1]: 2019-11-22T19:08:14.620Z 200 OK /policies
2019-11-22T19:08:14.636956+00:00 app[web.1]: at=info method=GET path="/policies" request_id=bc4486a2-4a2f-465a-a160-95878f1e3c19 fwd="70.132.33.80" user_agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:72.0) Gecko/20100101 Firefox/72.0

Is that deprecation warning anything we should be concerned about? And are the double logs (the last two lines) expected because there's no way to turn off the fastboot logging right now?

For comparison: when I turn off fastboot but stay on this branch, I see:

2019-11-22T19:15:50.190825+00:00 app[web.1]: at=info method=GET path="/policies" request_id=8bfe313e-0abe-430e-8843-289c6ff03bcb fwd="70.132.33.85" service=0ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:72.0) Gecko/20100101 Firefox/72.0"
2019-11-22T19:15:50.194414+00:00 app[web.1]: measure#nginx.service=0.011 request_id=8bfe313e-0abe-430e-8843-289c6ff03bcb
2019-11-22T19:15:50.193860+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=8bfe313e-0abe-430e-8843-289c6ff03bcb fwd="71.112.158.75,70.132.33.85" dyno=web.1 connect=1ms service=11ms status=200 bytes=2345 protocol=https

When I switch back to current master (ae7834e), with fastboot off I see:

2019-11-22T19:31:43.494965+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=9f93cd7a-1e5c-4cf1-85e9-a77d5ca309fc fwd="71.112.158.75,70.132.33.75" dyno=web.1 connect=0ms service=6ms status=200 bytes=2345 protocol=https
2019-11-22T19:31:43.491210+00:00 app[web.1]: at=info method=GET path="/policies" request_id=9f93cd7a-1e5c-4cf1-85e9-a77d5ca309fc fwd="71.112.158.75" service=0ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:72.0) Gecko/20100101 Firefox/72.0"

With USE_FASTBOOT=1 on ae7834e, I see:

2019-11-22T19:37:23.038905+00:00 app[web.1]: (node:19) [DEP0066] DeprecationWarning: OutgoingMessage.prototype._headers is deprecated
2019-11-22T19:37:23.376964+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=338d1ac1-ce1a-48fe-8835-aece603a3709 fwd="71.112.158.75,70.132.60.156" dyno=web.1 connect=1ms service=369ms status=200 bytes=5834 protocol=https
2019-11-22T19:37:23.364369+00:00 app[web.1]: 2019-11-22T19:37:23.363Z 200 OK /policies

Ah, so looks like the deprecation warning isn't from this branch.

So knowing all that, is everything as you'd expect?

---

Anyway, the only thing I'm sure about: for consistency, could you please add double quotes around the user agent? The backend log messages with user agents look like this:

2019-11-22T19:07:48.283299+00:00 app[web.1]: at=info method=GET path="/api/v1/me" request_id=d5c2c861-8cb4-4100-b8ba-aa21ca61b730 fwd="70.132.33.87" service=7ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:72.0) Gecko/20100101 Firefox/72.0"

[carols10cents]

Add double quotes around the user agent please. Thanks! ❤️

[kzys]

Yes. npm run start:{local, live, etc} use ember serve, whereas the production Heroku environment uses fastboot.js. While I'm really not so sure why we cannot simply use ember serve in production, not seeing logs from these npm run ... commands is expected.

Having double logs is annoying/odd, I agree. But this one, we would need to change Fastboot-related packages first.

[jtgeibel]

Having double logs is annoying/odd, I agree. But this one, we would need to change Fastboot-related packages first.

I'm fine with this duplication for now, but log sizes have been an issue in the past so we'll need to remove the extra line before enabling too many routes.

@bors r+

[bors]

📌 Commit 5ebd4bc has been approved by jtgeibel

[bors]

⌛ Testing commit 5ebd4bc with merge aaacc50...

[bors]

☀️ Test successful - checks-travis
Approved by: jtgeibel
Pushing aaacc50 to master...