defmodule TimeLog.TimePlug do import Plug.Conn require Logger alias TimeLog.PreLogPlug @bahaviour Plug @moduledoc ~S""" This plug stops the time a request takes. The plug needs to be called as early in the `endpoint.ex` as possible, ideally right after the socked received a request. Additionally the get_duration function can be called from everywhere in order to know how long the request took so far. """ def init(_opts) do {} end def call(conn, _opts) do start_time = Time.utc_now conn |> put_private(:time_plug_start_time, start_time) |> Plug.Conn.register_before_send(&log_response(&1, start_time)) end def log_response(conn, start_time) do [c_id] = get_resp_header(conn, "correlation_id") if :controller_body in Map.keys(conn.private) do http_struct = %{method: conn.method, url: conn.request_path, query: conn.query_string, header: inspect(conn.resp_headers), ip_address: PreLogPlug.get_ip(conn), body: Poison.encode!(conn.private[:controller_body]), status_code: conn.status, duration_ms: get_duration(start_time)} Logger.info(Poison.encode!(%{correlation_id: c_id, type: "Response", http: http_struct}), application_log: 1) else http_struct = %{method: conn.method, url: conn.request_path, query: conn.query_string, header: inspect(conn.resp_headers), ip_address: PreLogPlug.get_ip(conn), body: "There was no body for this request", status_code: conn.status, duration_ms: get_duration(start_time)} Logger.info(Poison.encode!(%{correlation_id: c_id, type: "Response", http: http_struct}), application_log: 1) end conn end @doc ~S""" Returns the time in ms the request took so far. May be called with either a Time struct https://hexdocs.pm/elixir/Time.html or with the current conn https://hexdocs/pm/plug/Plug.Conn.html. ## Examples iex> TimeLog.TimePlug.get_duration(conn) ~T[09:24:20.296862] iex> start_time = Time.utc_now ... ... iex> TimeLog.TimePlug.get_duration(start_time) 65 """ @spec get_duration(Time)::Time def get_duration(start_time = %Time{}) do Time.utc_now |> Time.diff(start_time, :milliseconds) |> round end @spec get_duration(Plug.Conn)::Time def get_duration(conn = %Plug.Conn{}) do Time.utc_now |> Time.diff(conn.private[:time_plug_start_time], :milliseconds) |> round end end # ----------------------------------------------------------------------- defmodule TimeLog.PreLogPlug do import Plug.Conn require Logger @bahaviour Plug @moduledoc ~S""" This plug logs the incoming requests. It logs the IP address and has the ability to anonymize the IP address if set in config. Allows calls to get_ip from other apps too. """ def init(_opts) do {} end def call(conn, _opts) do log_request conn end def log_request(conn) do unless conn.request_path in Application.get_env(:time_log, :ignore_urls) do [c_id] = if is_nil(get_resp_header(conn, "correlation_id")), do: get_resp_header(conn, "x-request-id"), else: get_resp_header(conn, "correlation_id") http_struct = %{method: conn.method, url: conn.request_path, query: conn.query_string, ip_address: get_ip(conn), header: inspect(conn.req_headers), params: Poison.encode!(conn.params)} Logger.info Poison.encode!(%{correlation_id: c_id, type: "Request", http: http_struct}), application_log: 1 end conn end def get_ip(conn) do header_map = conn.req_headers |> Enum.into(%{}) ip = if is_nil(header_map["x-forwarded-for"]), do: "Not forwarded", else: header_map["x-forwarded-for"] |> String.split(",") |> List.first Logger.debug "IP: #{ip}" cond do ip in Application.get_env(:time_log, :internal_ips) -> Application.get_env(:time_log, :internal_name) Application.get_env(:time_log, :anonymize_ips?) -> String.replace(ip, "\.\d{1,3}$", "\.XXX") true -> ip end end end