plug_accesslog

defmodule Plug.AccessLog.DefaultFormatter do
  @moduledoc """
  Default log message formatter.
  """

  alias Plug.AccessLog.DefaultFormatter

  @behaviour Plug.AccessLog.Formatter

  @doc """
  Formats a log message.

  The following formatting directives are available:

  - `%%` - Percentage sign
  - `%a` - Remote IP-address
  - `%b` - Size of response in bytes. Outputs "-" when no bytes are sent.
  - `%B` - Size of response in bytes. Outputs "0" when no bytes are sent.
  - `%{VARNAME}C` - Cookie sent by the client
  - `%D` - Time taken to serve the request (microseconds)
  - `%{VARNAME}e` - Environment variable contents
  - `%h` - Remote hostname
  - `%{VARNAME}i` - Header line sent by the client
  - `%l` - Remote logname
  - `%m` - Request method
  - `%M` - Time taken to serve the request (milliseconds)
  - `%{VARNAME}o` - Header line sent by the server
  - `%P` - The process ID that serviced the request
  - `%q` - Query string (prepended with "?" or empty string)
  - `%r` - First line of HTTP request
  - `%>s` - Response status code
  - `%t` - Time the request was received in the format `[10/Jan/2015:14:46:18 +0100]`
  - `%T` - Time taken to serve the request (full seconds)
  - `%{UNIT}T` - Time taken to serve the request in the given UNIT
  - `%u` - Remote user
  - `%U` - URL path requested (without query string)
  - `%v` - Server name
  - `%V` - Server name (canonical)

  **Note for %b and %B**: To determine the size of the response the
  "Content-Length" will be inspected and, if available, returned
  unverified. If the header is not present the response body will be
  inspected using `byte_size/1`.

  **Note for %h**: The hostname will always be the ip of the client (same as `%a`).

  **Note for %l**: Always a dash ("-").

  **Note for %r**: For now the http version is always logged as "HTTP/1.1",
  regardless of the true http version.

  **Note for %T**: Rounding happens, so "0.6 seconds" will be reported as "1 second".

  **Note for %{UNIT}T**: Available units are `s` for seconds (same as `%T`),
  `ms` for milliseconds (same as `M`) and `us` for microseconds (same as `%D`).

  **Note for %V**: Alias for `%v`.
  """
  def format(format, conn), do: log([], conn, format)


  # Internal construction methods

  defp log(message, _conn, ""), do: message |> Enum.reverse() |> IO.iodata_to_binary()

  defp log(message, conn, << "%%", rest :: binary >>) do
    [ "%" | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%a", rest :: binary >>) do
    [ DefaultFormatter.RemoteIPAddress.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%b", rest :: binary >>) do
    [ DefaultFormatter.ResponseBytes.format(conn, "-") | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%B", rest :: binary >>) do
    [ DefaultFormatter.ResponseBytes.format(conn, "0") | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%D", rest :: binary >>) do
    [ DefaultFormatter.RequestServingTime.format(conn, :microseconds) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%h", rest :: binary >>) do
    [ DefaultFormatter.RemoteIPAddress.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%l", rest :: binary >>) do
    [ "-" | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%m", rest :: binary >>) do
    [ conn.method | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%M", rest :: binary >>) do
    [ DefaultFormatter.RequestServingTime.format(conn, :milliseconds) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%P", rest :: binary >>) do
    [ inspect(conn.owner) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%q", rest :: binary >>) do
    [ DefaultFormatter.QueryString.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%r", rest :: binary >>) do
    [ DefaultFormatter.RequestLine.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%>s", rest :: binary >>) do
    [ to_string(conn.status) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%t", rest :: binary >>) do
    [ DefaultFormatter.RequestTime.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%T", rest :: binary >>) do
    [ DefaultFormatter.RequestServingTime.format(conn, :seconds) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%u", rest :: binary >>) do
    [ DefaultFormatter.RemoteUser.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%U", rest :: binary >>) do
    [ DefaultFormatter.RequestPath.format(conn) | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%v", rest :: binary >>) do
    [ conn.host | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%V", rest :: binary >>) do
    [ conn.host | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << "%{", rest :: binary >>) do
    [ var, rest ] = rest |> String.split("}", parts: 2)

    << vartype :: binary-1, rest :: binary >> = rest

    append = case vartype do
      "C" -> DefaultFormatter.RequestCookie.format(conn, var)
      "e" -> DefaultFormatter.Environment.format(conn, var)
      "i" -> DefaultFormatter.RequestHeader.format(conn, var)
      "o" -> DefaultFormatter.ResponseHeader.format(conn, var)
      "T" -> DefaultFormatter.RequestServingTime.format(conn, var)
      _   -> "-"
    end

    [ append | message ]
    |> log(conn, rest)
  end

  defp log(message, conn, << char, rest :: binary >>) do
    [ << char >> | message ]
    |> log(conn, rest)
  end
end