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 = DateTime.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_correlation_id(conn)
Logger.info(Jason.encode!(%{correlation_id: c_id, type: "Response", http: create_http_map(conn)}),
request_log: 1
)
conn
end
defp create_http_map(conn) do
%{
method: conn.method,
url: conn.request_path,
query: sanitize_query_string(conn),
header: inspect(conn.resp_headers),
ip_address: get_ip(conn),
body: sanitize_body(conn.private),
status_code: conn.status,
duration_ms: get_duration(conn)
}
end
@doc ~S"""
Returns the time in ms the request took so far.
May be called with either a DateTime struct `DateTime` 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 = DateTime.utc_now
...
...
iex> TimeLog.TimePlug.get_duration(start_time) # Request the duration with a `DateTime` struct
65
```
"""
@spec get_duration(DateTime) :: Integer
def get_duration(start_time = %DateTime{}) do
DateTime.utc_now()
|> DateTime.diff(start_time, :millisecond)
|> round
end
@spec get_duration(Plug.Conn) :: Integer
def get_duration(conn = %Plug.Conn{}) do
DateTime.utc_now()
|> DateTime.diff(conn.private[:time_plug_start_time], :millisecond)
|> 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
!is_nil(from_config(:internal_ips)) and ip in from_config(:internal_ips) ->
internal_name()
!is_nil(from_config(:shop_ips)) and ip in from_config(:shop_ips) ->
shop_name()
!is_nil(from_config(:anonymize_ips?)) and from_config(:anonymize_ips?) ->
String.replace(ip, ~r/\.\d{1,3}$/, ".XXX")
true ->
ip
end
end
def sanitize_query_string(conn = %Plug.Conn{}), do: sanitize(conn.query_string)
def sanitize_query_string(_), do: ""
def sanitize_body(private_map) do
if Map.has_key?(private_map, :controller_body) do
sanitize(private_map[:controller_body])
else
"There is no body"
end
end
def sanitize(maps) when is_list(maps) do
Enum.map(maps, &sanitize/1)
end
def sanitize(log_map) when is_map(log_map) do
sanitize_list =
from_config(:sanitize_fields, [])
|> Enum.map(&String.split(&1, "."))
Enum.map(log_map, &sanitize_recursiv(&1, %{}, sanitize_list))
|> Enum.reduce(%{}, fn {key, value}, acc -> Map.put(acc, key, value) end)
end
def sanitize(query_string) when is_binary(query_string) do
if String.contains?(query_string, from_config(:sanitize_fields, [])) do
from_config(:sanitize_string, "*")
else
query_string
end
end
def sanitize(any), do: any
def sanitize_recursiv({key, map}, parent, sanitize_list) when is_map(map) and is_map(parent) do
{_, sanitize_list} = check_sanitize_list(key, sanitize_list)
result =
Enum.map(map, &sanitize_recursiv(&1, map, sanitize_list))
|> Enum.reduce(%{}, fn {key, value}, acc -> Map.put(acc, key, value) end)
{key, result}
end
def sanitize_recursiv({key, list}, parent, sanitize_list) when is_list(list) and is_list(parent) do
{_, sanitize_list} = check_sanitize_list(key, sanitize_list)
Enum.map(list, &sanitize_recursiv({nil, &1}, list, sanitize_list))
end
def sanitize_recursiv({key, map}, parent, sanitize_list) when is_map(map) and is_list(parent) do
{_, sanitize_list} = check_sanitize_list(key, sanitize_list)
Enum.map(map, &sanitize_recursiv(&1, map, sanitize_list))
|> Enum.into(%{})
end
def sanitize_recursiv({key, list}, parent, sanitize_list) when is_list(list) and is_map(parent) do
{_, sanitize_list} = check_sanitize_list(key, sanitize_list)
{key, Enum.map(list, &sanitize_recursiv({nil, &1}, list, sanitize_list))}
end
def sanitize_recursiv({key, value}, _parent, sanitize_list) do
{sanitize, _sanitize_list} = check_sanitize_list(key, sanitize_list)
sanitize_value(key, value, sanitize)
end
def sanitize_value(nil, value, sanitize), do: if(sanitize, do: from_config(:sanitize_string, "*"), else: value)
def sanitize_value(key, value, sanitize),
do: if(sanitize, do: {key, from_config(:sanitize_string, "*")}, else: {key, value})
def check_sanitize_list(key, sanitize_list) do
wildcard = from_config(:wildcard_string, "*")
sanitize_keywords = Enum.map(sanitize_list, &check_sanitize_fields(key, &1, wildcard))
{Keyword.has_key?(sanitize_keywords, true), Keyword.values(sanitize_keywords)}
end
def check_sanitize_fields(_key, [head | tail], wildcard) when head === wildcard and tail == [],
do: {true, [head | tail]}
def check_sanitize_fields(key, origin_list = [origin_head | [head | tail]], wildcard) when origin_head === wildcard do
if sanitize_check(key, head), do: {true, tail}, else: {false, origin_list}
end
def check_sanitize_fields(_key, list, _wildcard) when list == [], do: {false, list}
def check_sanitize_fields(key, [head | tail], _wildcard),
do: if(sanitize_check(key, head), do: {true, tail}, else: {false, []})
def sanitize_check(key, sanitize_field), do: key |> to_string == sanitize_field
defp internal_name() do
if !is_nil(from_config(:internal_name)) do
from_config(:internal_name)
else
"Internal IP"
end
end
defp shop_name() do
if !is_nil(from_config(:shop_name)) do
from_config(:shop_name)
else
"Shop IP"
end
end
def from_config(atom) when is_atom(atom) do
Application.get_env(:time_log, atom)
end
def from_config(atom, default) when is_atom(atom) do
Application.get_env(:time_log, atom, default)
end
@doc ~S"""
Get the correlation_id.
"""
@spec get_correlation_id(Plug.Conn) :: String
def get_correlation_id(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")
c_id
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
