My end goal is to have all logs be valid JSON and send to stdout, but I’ve seem to run into a wall.
Initial I wanted to re-use the functionality that’s built into
:console and just use my own formatter,
this way I could ensure everything coming from Logger would be valid and :console would handle message buffering and sending to stdio.
I ended up coming up with this:
config :logger, :console,
format: {Logger.Formatters.Json, :format}
defmodule Logger.Formatters.Json do
alias Logger.{Utils}
@doc "log formatter replacement. Injected through the :format key"
def format(level, msg, timestamp, metadata) do
%{
level: level,
time: format_time(timestamp),
msg: (msg |> IO.iodata_to_binary)
}
|> Map.merge(Enum.into(metadata, %{}))
|> Poison.encode!
|> Kernel.<>("\n")
end
defp format_time({date, time}) do
[Utils.format_date(date), Utils.format_time(time)]
|> Enum.join(" ")
end
end
> Logger.debug('test')
:ok
{"time":"2017-02-13 14:32:11.106","msg":"test","level":"debug"}
This was a good start but now want to log more information like status, action, controller, etc. so I set off to create a new Plug. The plug would gather this information from conn but when it came to actually sending it to the logger I ran into my first problem, logging more than just a string.
Currently the logger handles some of the utility responsibilities before calling the formatter which is really nice but it prevents me from passing in anything besides a string for the message arg. Encoding the data structure could work but it would make it less readable and would require the log to be parsed twice.
Instead of doing this I would prefer to have a relatively flat JSON structure similar to how metadata is currently handled.
This actually lead me to try and put status, method, etc into the metadata which actually worked but it felt wrong and required two before send hooks:
def call(conn, opts) do
start_time = current_time()
Conn.register_before_send(conn, fn conn ->
stop_time = current_time()
duration = System.convert_time_unit(stop_time - start_time, :native, :micro_seconds)
stats = []
|> Keyword.put(:method, conn.method)
|> Keyword.put(:path, conn.request_path)
|> Keyword.merge(formatted_phoenix_info(conn))
|> Keyword.put(:status, conn.status)
|> Keyword.put(:duration, (formatted_diff(duration) |> IO.iodata_to_binary))
Logger.info(fn -> {"", stats} end)
conn
end)
end
{"time":"2017-02-13 16:28:47.568","status":200,"request_id":"u3iaoaiid9u3ddi877573bee7v2hdl5f","path":"/","msg":"META","method":"GET","level":"info","format":"html","duration":"26ms","controller":"Sample.PageController","action":"index"}
Ok so now metadata is gathered and calling Logger directly works but what about Ectos logger?
I can write my own ecto logger as well but I’m not really sure if I’m going about this the right way.
Is there an easier way to do all of this?
Should I be using something like bleacherreport’s ecto_logger_json and plug_logger_json? If so, I just don’t know how to handle direct Logger calls.
I’d also want to disable the default Phoenix Logger since I’d be gathering most of that information through the custom plug.
Any input or feedback is greatly appreciated.
