logger.ex

defmodule Phoenix.Logger do
  @moduledoc """
  Instrumenter to handle logging of various instrumentation events.

  ## Instrumentation

  Phoenix uses the `:telemetry` library for instrumentation. The following events
  are published by Phoenix with the following measurements and metadata:

    * `[:phoenix, :endpoint, :init]` - dispatched by `Phoenix.Endpoint` after your
      Endpoint supervision tree successfully starts
      * Measurement: `%{system_time: system_time}`
      * Metadata: `%{pid: pid(), config: Keyword.t(), module: module(), otp_app: atom()}`
      * Disable logging: This event is not logged

    * `[:phoenix, :endpoint, :start]` - dispatched by `Plug.Telemetry` in your endpoint,
      usually after code reloading
      * Measurement: `%{system_time: system_time}`
      * Metadata: `%{conn: Plug.Conn.t, options: Keyword.t}`
      * Options: `%{log: Logger.level | false}`
      * Disable logging: In your endpoint `plug Plug.Telemetry, ..., log: Logger.level | false`
      * Configure log level dynamically: `plug Plug.Telemetry, ..., log: {Mod, Fun, Args}`

    * `[:phoenix, :endpoint, :stop]` - dispatched by `Plug.Telemetry` in your
      endpoint whenever the response is sent
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{conn: Plug.Conn.t, options: Keyword.t}`
      * Options: `%{log: Logger.level | false}`
      * Disable logging: In your endpoint `plug Plug.Telemetry, ..., log: Logger.level | false`
      * Configure log level dynamically: `plug Plug.Telemetry, ..., log: {Mod, Fun, Args}`

    * `[:phoenix, :router_dispatch, :start]` - dispatched by `Phoenix.Router`
      before dispatching to a matched route
      * Measurement: `%{system_time: System.system_time}`
      * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom], log: Logger.level | false}`
      * Disable logging: Pass `log: false` to the router macro, for example: `get("/page", PageController, :index, log: false)`
      * Configure log level dynamically: `get("/page", PageController, :index, log: {Mod, Fun, Args})`

    * `[:phoenix, :router_dispatch, :exception]` - dispatched by `Phoenix.Router`
      after exceptions on dispatching a route
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{conn: Plug.Conn.t, kind: :throw | :error | :exit, reason: term(), stacktrace: Exception.stacktrace()}`
      * Disable logging: This event is not logged

    * `[:phoenix, :router_dispatch, :stop]` - dispatched by `Phoenix.Router`
      after successfully dispatching a matched route
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom], log: Logger.level | false}`
      * Disable logging: This event is not logged

    * `[:phoenix, :error_rendered]` - dispatched at the end of an error view being rendered
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{conn: Plug.Conn.t, status: Plug.Conn.status, kind: Exception.kind, reason: term, stacktrace: Exception.stacktrace}`
      * Disable logging: Set `render_errors: [log: false]` on your endpoint configuration

    * `[:phoenix, :socket_connected]` - dispatched by `Phoenix.Socket`, at the end of a socket connection
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{endpoint: atom, transport: atom, params: term, connect_info: map, vsn: binary, user_socket: atom, result: :ok | :error, serializer: atom, log: Logger.level | false}`
      * Disable logging: `use Phoenix.Socket, log: false` or `socket "/foo", MySocket, websocket: [log: false]` in your endpoint

    * `[:phoenix, :channel_joined]` - dispatched at the end of a channel join
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{result: :ok | :error, params: term, socket: Phoenix.Socket.t}`
      * Disable logging: This event cannot be disabled

    * `[:phoenix, :channel_handled_in]` - dispatched at the end of a channel handle in
      * Measurement: `%{duration: native_time}`
      * Metadata: `%{event: binary, params: term, socket: Phoenix.Socket.t}`
      * Disable logging: This event cannot be disabled

  To see an example of how Phoenix LiveDashboard uses these events to create
  metrics, visit <https://hexdocs.pm/phoenix_live_dashboard/metrics.html>.

  ## Parameter filtering

  When logging parameters, Phoenix can filter out sensitive parameters
  such as passwords and tokens. Parameters to be filtered can be
  added via the `:filter_parameters` option:

      config :phoenix, :filter_parameters, ["password", "secret"]

  With the configuration above, Phoenix will filter any parameter
  that contains the terms `password` or `secret`. The match is
  case sensitive.

  Phoenix's default is `["password"]`.

  Phoenix can filter all parameters by default and selectively keep
  parameters. This can be configured like so:

      config :phoenix, :filter_parameters, {:keep, ["id", "order"]}

  With the configuration above, Phoenix will filter all parameters,
  except those that match exactly `id` or `order`. If a kept parameter
  matches, all parameters nested under that one will also be kept.

  ## Dynamic log level

  In some cases you may wish to set the log level dynamically
  on a per-request basis. To do so, set the `:log` option to
  a tuple, `{Mod, Fun, Args}`. The `Plug.Conn.t()` for the
  request will be prepended to the provided list of arguments.

  When invoked, your function must return a
  [`Logger.level()`](`t:Logger.level()/0`) or `false` to
  disable logging for the request.

  For example, in your Endpoint you might do something like this:

        # lib/my_app_web/endpoint.ex
        plug Plug.Telemetry,
          event_prefix: [:phoenix, :endpoint],
          log: {__MODULE__, :log_level, []}

        # Disables logging for routes like /status/*
        def log_level(%{path_info: ["status" | _]}), do: false
        def log_level(_), do: :info

  ## Disabling

  When you are using custom logging system it is not always desirable to enable
  `#{inspect(__MODULE__)}` by default. You can always disable this in general by:

      config :phoenix, :logger, false
  """

  require Logger

  @doc false
  def install do
    handlers = %{
      [:phoenix, :endpoint, :start] => &__MODULE__.phoenix_endpoint_start/4,
      [:phoenix, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4,
      [:phoenix, :router_dispatch, :start] => &__MODULE__.phoenix_router_dispatch_start/4,
      [:phoenix, :error_rendered] => &__MODULE__.phoenix_error_rendered/4,
      [:phoenix, :socket_connected] => &__MODULE__.phoenix_socket_connected/4,
      [:phoenix, :channel_joined] => &__MODULE__.phoenix_channel_joined/4,
      [:phoenix, :channel_handled_in] => &__MODULE__.phoenix_channel_handled_in/4
    }

    for {key, fun} <- handlers do
      :telemetry.attach({__MODULE__, key}, key, fun, :ok)
    end
  end

  @doc false
  def duration(duration) do
    duration = System.convert_time_unit(duration, :native, :microsecond)

    if duration > 1000 do
      [duration |> div(1000) |> Integer.to_string(), "ms"]
    else
      [Integer.to_string(duration), "µs"]
    end
  end

  @doc false
  def filter_values(values, params \\ Application.get_env(:phoenix, :filter_parameters, []))
  def filter_values(values, {:discard, params}), do: discard_values(values, params)
  def filter_values(values, {:keep, params}), do: keep_values(values, params)
  def filter_values(values, params), do: discard_values(values, params)

  defp discard_values(%{__struct__: mod} = struct, _params) when is_atom(mod) do
    struct
  end

  defp discard_values(%{} = map, params) do
    Enum.into(map, %{}, fn {k, v} ->
      if is_binary(k) and String.contains?(k, params) do
        {k, "[FILTERED]"}
      else
        {k, discard_values(v, params)}
      end
    end)
  end

  defp discard_values([_ | _] = list, params) do
    Enum.map(list, &discard_values(&1, params))
  end

  defp discard_values(other, _params), do: other

  defp keep_values(%{__struct__: mod}, _params) when is_atom(mod), do: "[FILTERED]"

  defp keep_values(%{} = map, params) do
    Enum.into(map, %{}, fn {k, v} ->
      if is_binary(k) and k in params do
        {k, discard_values(v, [])}
      else
        {k, keep_values(v, params)}
      end
    end)
  end

  defp keep_values([_ | _] = list, params) do
    Enum.map(list, &keep_values(&1, params))
  end

  defp keep_values(_other, _params), do: "[FILTERED]"

  defp log_level(nil, _conn), do: :info
  defp log_level(level, _conn) when is_atom(level), do: level

  defp log_level({mod, fun, args}, conn) when is_atom(mod) and is_atom(fun) and is_list(args) do
    apply(mod, fun, [conn | args])
  end

  ## Event: [:phoenix, :endpoint, *]

  @doc false
  def phoenix_endpoint_start(_, _, %{conn: conn} = metadata, _) do
    case log_level(metadata[:options][:log], conn) do
      false ->
        :ok

      level ->
        Logger.log(level, fn ->
          %{method: method, request_path: request_path} = conn
          [method, ?\s, request_path]
        end)
    end
  end

  @doc false
  def phoenix_endpoint_stop(_, %{duration: duration}, %{conn: conn} = metadata, _) do
    case log_level(metadata[:options][:log], conn) do
      false ->
        :ok

      level ->
        Logger.log(level, fn ->
          %{status: status, state: state} = conn
          status = status_to_string(status)
          [connection_type(state), ?\s, status, " in ", duration(duration)]
        end)
    end
  end

  defp connection_type(:set_chunked), do: "Chunked"
  defp connection_type(_), do: "Sent"

  ## Event: [:phoenix, :error_rendered]

  @doc false
  def phoenix_error_rendered(_, _, %{log: false}, _), do: :ok

  def phoenix_error_rendered(_, _, %{log: level, status: status, kind: kind, reason: reason}, _) do
    Logger.log(level, fn ->
      [
        "Converted ",
        Atom.to_string(kind),
        ?\s,
        error_banner(kind, reason),
        " to ",
        status_to_string(status),
        " response"
      ]
    end)
  end

  defp status_to_string(status) do
    status |> Plug.Conn.Status.code() |> Integer.to_string()
  end

  defp error_banner(:error, %type{}), do: inspect(type)
  defp error_banner(_kind, reason), do: inspect(reason)

  ## Event: [:phoenix, :router_dispatch, :start]

  @doc false
  def phoenix_router_dispatch_start(_, _, %{log: false}, _), do: :ok

  def phoenix_router_dispatch_start(_, _, metadata, _) do
    %{log: level, conn: conn, plug: plug} = metadata
    level = log_level(level, conn)
    log_module = metadata[:log_module] || plug

    Logger.log(level, fn ->
      %{
        pipe_through: pipe_through,
        plug_opts: plug_opts
      } = metadata

      [
        "Processing with ",
        inspect(log_module),
        maybe_action(plug_opts),
        ?\n,
        "  Parameters: ",
        params(conn.params),
        ?\n,
        "  Pipelines: ",
        inspect(pipe_through)
      ]
    end)
  end

  defp maybe_action(action) when is_atom(action), do: [?., Atom.to_string(action), ?/, ?2]
  defp maybe_action(_), do: []

  defp params(%Plug.Conn.Unfetched{}), do: "[UNFETCHED]"
  defp params(params), do: params |> filter_values() |> inspect()

  ## Event: [:phoenix, :socket_connected]

  @doc false
  def phoenix_socket_connected(_, _, %{log: false}, _), do: :ok

  def phoenix_socket_connected(_, %{duration: duration}, %{log: level} = meta, _) do
    Logger.log(level, fn ->
      %{
        transport: transport,
        params: params,
        user_socket: user_socket,
        result: result,
        serializer: serializer
      } = meta

      [
        connect_result(result),
        inspect(user_socket),
        " in ",
        duration(duration),
        "\n  Transport: ",
        inspect(transport),
        "\n  Serializer: ",
        inspect(serializer),
        "\n  Parameters: ",
        inspect(filter_values(params))
      ]
    end)
  end

  defp connect_result(:ok), do: "CONNECTED TO "
  defp connect_result(:error), do: "REFUSED CONNECTION TO "

  ## Event: [:phoenix, :channel_joined]

  @doc false
  def phoenix_channel_joined(_, %{duration: duration}, %{socket: socket} = metadata, _) do
    channel_log(:log_join, socket, fn ->
      %{result: result, params: params} = metadata

      [
        join_result(result),
        socket.topic,
        " in ",
        duration(duration),
        "\n  Parameters: ",
        inspect(filter_values(params))
      ]
    end)
  end

  defp join_result(:ok), do: "JOINED "
  defp join_result(:error), do: "REFUSED JOIN "

  ## Event: [:phoenix, :channel_handle_in]

  @doc false
  def phoenix_channel_handled_in(_, %{duration: duration}, %{socket: socket} = metadata, _) do
    channel_log(:log_handle_in, socket, fn ->
      %{event: event, params: params} = metadata

      [
        "HANDLED ",
        event,
        " INCOMING ON ",
        socket.topic,
        " (",
        inspect(socket.channel),
        ") in ",
        duration(duration),
        "\n  Parameters: ",
        inspect(filter_values(params))
      ]
    end)
  end

  defp channel_log(_log_option, %{topic: "phoenix" <> _}, _fun), do: :ok

  defp channel_log(log_option, %{private: private}, fun) do
    if level = Map.get(private, log_option) do
      Logger.log(level, fun)
    end
  end
end