Use Elixir Logger and improve formatting of requests

[chrismccord]

No description provided.

[chrismccord]

What we have today to start the discussion:

2014-07-29 09:44:35:02 GET: []
    controller: Elixir.MyApp.PageController
    action:     index
    accept:     text/html
    parameters: %{"foo" => "bar"}
  resp_time=10ms status=200 GET

[scrogson]

I've been working on a audit logging project at work. I think what ever data is available to the logs should be extendable by the user. Possibly a map that can have custom key-values merged into a custom struct where the output can be customized via a protocol?

I haven't dug into the Logger docs all that much yet. But we should maybe provide a default backend that can be swapped out for something else if desired (i.e. a Logstash or Syslog backend).

[josevalim]

There is no need for Phoenix to provide a new backend because Logger supports metadata (i.e. you can add whatever you want to logs).

[jeregrine]

@scrogson Elixir Logger allows any backend you'd like and any format you'd like.

We'd be defining a custom format for phoenix and which metadata to send.

[scrogson]

Ah, sorry. I think I meant format instead of backend.

[jeregrine]

@scrogson default backend flushes to stdout. Custom backends can send to file or logstash or syslog etc.

Format is what it logs to those sources.

[scrogson]

Yep. Got it. Thanks for the clarity.

[josevalim]

Ok. I am going to setup the goals here:

1. The Logger needs to be useful in development and production
2. It would be nice if we could share code with Plug
3. The messages should be clear and clean

One of the first things we need to do is to add a request_id to metadata (or should we abbreviate it as rid?). So everything logged in that request is properly tagged with that request identifier. Here is the config I recommend for Phoenix:

# config.exs
config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:user_id, :request_id]

# prod.exs
config :logger, :level, :info

We added :user_id above to be an example to the user on how to add app specific metadata. The format is the Elixir default too.

If we want to share information with plug, it means we need to segregate which information is available to Plug and what is available for Phoenix. It is also important to figure out what is info and what is debug data, here is my proposal:

09:44:35.021 request_id=ac364f [info]  GET /users/1
09:44:35.023 request_id=ac364f [debug] Processing by MyApp.PageController.index/2
  Accept: text/html
  Parameters: ...
09:44:35.024 request_id=ac364f [info]  Sent 200 OK in 3ms

The first and last messages would be handled by a logger plug provided by Plug. The request_id will be added by this plug too. Sent may also be Chunked if a chunk style was chosen. Thoughts?

[jeregrine]

@josevalim
When you say information shared with plug do you envision that plug would be logging the INFO level information and phoenix doing debug level?

Would we log each chunk as its sent as well? Or just when the chunked connection is closed?

[josevalim]

When you say information shared with plug do you envision that plug would be logging the INFO level information and phoenix doing debug level?

Yes.

Would we log each chunk as its sent as well? Or just when the chunked connection is closed?

I would log just start. Each chunk would definitely be too much and when the chunked connection is closed is hard to specify.

[jeregrine]

@josevalim so plug would create the request id and send it with the conn. And it would also probably setup a before_send closure with the current_timestamp to log before it was sent. Got it.

[josevalim]

@jeregrine the request_id will be set by calling Logger.metadata/1. Everything else is correct!

[jeregrine]

Makes sense to me!

[jeregrine]

So I am going to do two pr's one for plug, and one for this. I will reference the two to this.