defmodule TimeLog.TimePlug do import Plug.Conn require Logger @moduledoc ~S""" This plug stops the time a request takes. Also, this module delivers additional useful functionality 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. Allows calls to get_ip from other apps too. """ @doc false def init(_opts) do {} end @doc "Call to TimePlug that initiates the duration measurement and schedules Response logging to take place before sending the response." @spec call(Plug.Conn, Map)::Plug.Conn def call(conn, _opts) do start_time = Time.utc_now conn |> put_private(:time_plug_start_time, start_time) end @doc ~S""" Log the response including the IP address, correlation_id and headers. """ @spec log_response(Plug.Conn)::Plug.Conn def log_response(conn) do [c_id] = get_resp_header conn, "correlation_id" Logger.info Poison.encode!(%{correlation_id: c_id, type: "Response", http: create_http_map conn}), application_log: 1 conn end defp create_http_map(conn) do if :controller_body in Map.keys(conn.private) do %{method: conn.method, url: conn.request_path, query: conn.query_string, header: inspect(conn.resp_headers), ip_address: get_ip(conn), body: Poison.encode!(conn.private[:controller_body]), status_code: conn.status, duration_ms: get_duration(conn)} else %{method: conn.method, url: conn.request_path, query: conn.query_string, header: inspect(conn.resp_headers), ip_address: get_ip(conn), body: "There was no body for this request", status_code: conn.status, duration_ms: get_duration(conn)} end end @doc ~S""" Returns the time in ms the request took so far. May be called with either a Time struct `Time` or with the current conn `Plug.Conn`. ## Examples ``` iex> TimeLog.TimePlug.get_duration(conn) # Request the duration with a `Plug.Conn` struct 65 iex> start_time = Time.utc_now ... ... iex> TimeLog.TimePlug.get_duration(start_time) # Request the duration with a `Time` struct 65 ``` """ @spec get_duration(Time)::Integer 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 @doc ~S""" Returns the IP address in a Format fit for logging. If set in config the IP addresses retourned are anonymized by replacing the last digits with 'XXX'. Requests that use internal (e.g. company) Ip addresses can be filtered if set in config(`config :time_log, internal_ips: ["127.0.0.1"]`). """ @spec get_ip(Plug.Conn)::String def get_ip(conn) do header_map = conn.req_headers |> Enum.into(%{}) ip = if is_nil(header_map["x-forwarded-for"]), do: conn.remote_ip |> Tuple.to_list |> Enum.join(".") , 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, ~r/\.\d{1,3}$/, ".XXX" true -> ip end end @doc ~S""" Sets the body to be logged in the conn in the private part for the key `:controller_body`. The body will be included in the response logs if present. ## Example In a REST Api function that is called to send the result JSON. The output paramter may be any `Map` or `Struct`. ``` defp send_response(conn, output) do conn |> TimeLog.TimePlug.set_controller_body(output) |> json(output) end ``` """ @spec set_controller_body(Plug.Conn, Map)::Plug.Conn def set_controller_body(conn, body) do conn |> put_private(:controller_body, body) end end # ----------------------------------------------------------------------- defmodule TimeLog.PreLogPlug do import Plug.Conn require Logger alias TimeLog.TimePlug @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. """ @doc false def init(_opts) do {} end @doc "Call to PreLogPlug that initiates the request logging." @spec call(Plug.Conn, Map)::Plug.Conn def call(conn, _opts) do unless conn.request_path in Application.get_env(:time_log, :ignore_urls) do initiate_logging conn else conn end end @doc ~S""" Initiates Response logging and logs the incoming request. Ensures that responses are only logged if the corresponding request was logged as well. """ @spec initiate_logging(Plug.Conn)::Plug.Conn def initiate_logging(conn) 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_map = %{method: conn.method, url: conn.request_path, query: conn.query_string, ip_address: TimePlug.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_map}), application_log: 1 Plug.Conn.register_before_send conn, &TimePlug.log_response(&1) end end