Adding Logger and Updating Connection

.travis.yml

@@ -3,7 +3,7 @@ otp_release:
   - 17.1
 before_install:
   - git clone https://github.com/elixir-lang/elixir
-  - cd elixir && git checkout v0.15.0 && make && cd ..
+  - cd elixir && git checkout v0.15.1 && make && cd ..
 before_script:
   - export PATH=`pwd`/elixir/bin:$PATH
   - mix local.hex --force

README.md

@@ -479,9 +479,6 @@ config :phoenix, YourApp.Router,
   session_key: "_your_app_key",
   session_secret: "super secret"
 
-config :phoenix, :logger,
-  level: :error
-
 
 import_config "#{Mix.env}.exs"
 
@@ -498,9 +495,6 @@ config :phoenix, YourApp.Router,
   session_key: "_your_app_key",
   session_secret: "super secret"
 
-config :phoenix, :logger,
-  level: :debug
-
 
 ```
 
@@ -650,7 +644,7 @@ $ coffee -o priv/static/js -cw priv/src/static/cs
 - Middleware
   - [x] Plug Based Connection handling
   - [x] Code Reloading
-  - [ ] Enviroment Based logging with log levels with Elixir's Logger
+  - [x] Enviroment Based logging with log levels with Elixir's Logger
   - [x] Static File serving
 - Controllers
   - [x] html/json/text helpers

lib/phoenix/config.ex

@@ -34,7 +34,6 @@ defmodule Phoenix.Config do
       error_handler: true,
       cookies: false,
     ],
-    logger: [level: :error],
     template_engines: [
       eex: Phoenix.Template.EExEngine
     ],
@@ -55,7 +54,7 @@ defmodule Phoenix.Config do
 
   ## Examples
 
-      iex> Config.default([:logger, :level])
+      iex> Config.default([:router, :port])
       :error
 
   """
@@ -77,7 +76,7 @@ defmodule Phoenix.Config do
 
   ## Examples
 
-      iex> Config.get([:logger, :level])
+      iex> Config.get([:router, :port])
       :info
 
   """
@@ -96,10 +95,10 @@ defmodule Phoenix.Config do
 
   ## Examples
 
-      iex> Config.get!([:logger, :level])
+      iex> Config.get!([:router, :port])
       :info
 
-      iex(2)> Phoenix.Config.get!([:logger, :key_that_does_not_exist])
+      iex(2)> Phoenix.Config.get!([:router, :key_that_does_not_exist])
       ** (Phoenix.Config.UndefinedConfigError) [message: "No configuration found...
 
   """

lib/phoenix/controller.ex

@@ -132,7 +132,7 @@ defmodule Phoenix.Controller do
   end
   def render_view(conn, view_mod, layout_mod, template, assigns) do
     template     = template || action_name(conn)
-    content_type = response_content_type(conn)
+    content_type = response_content_type!(conn)
     ext         = MIME.extensions(content_type) |> Enum.at(0)
     status       = conn.status || 200
     conn         = prepare_for_render(conn, assigns, layout_mod, ext)

lib/phoenix/controller/connection.ex

@@ -84,14 +84,26 @@ defmodule Phoenix.Controller.Connection do
 
   Raises Errors.UnfetchedContentType if content type is not yet fetched
   """
+  def response_content_type!(conn) do
+    case response_content_type(conn) do
+      {:ok, resp} -> resp
+      {:error, msg} ->  raise %Errors.UnfetchedContentType{message: msg}
+    end
+  end
+
+  @doc """
+  Returns the String Mime content-type of response
+    {:ok, "text/html"}
+    {:error, "You must first call Plugs.ContentTypeFetcher.fetch/1"}
+  """
   def response_content_type(conn) do
     conn
     |> get_resp_header("content-type")
     |> Enum.at(0)
-    |> Kernel.||(raise %Errors.UnfetchedContentType{message:
-      "You must first call Plugs.ContentTypeFetcher.fetch/1"})
-    |> String.split(";")
-    |> Enum.at(0)
+    |> case do
+      nil -> {:error, "You must first call Plugs.ContentTypeFetcher.fetch/1"}
+      headers -> {:ok, headers |> String.split(";") |> Enum.at(0)}
+    end
   end
 
   @doc """

lib/phoenix/plugs/accepts.ex

@@ -15,7 +15,7 @@ defmodule Phoenix.Plugs.Accepts do
   def init(opts), do: opts
 
   def call(conn, extensions) do
-    primary_accept_extension = MIME.extensions(response_content_type(conn)) |> hd
+    primary_accept_extension = MIME.extensions(response_content_type!(conn)) |> hd
 
     if primary_accept_extension in extensions do
       conn

lib/phoenix/plugs/error_handler.ex

@@ -2,6 +2,7 @@ defmodule Phoenix.Plugs.ErrorHandler do
   @behaviour Plug.Wrapper
   alias Phoenix.Config
   alias Phoenix.Controller
+  require Logger
 
   def init(opts), do: opts
 
@@ -10,7 +11,8 @@ defmodule Phoenix.Plugs.ErrorHandler do
       func.(conn)
     catch
       :throw, {:halt, conn} -> conn
-      _kind, error ->
+      kind, error ->
+        Logger.error(Exception.format(kind, error))
         if Config.router(module, [:consider_all_requests_local]) do
           Controller.Action.error_with_trace(conn, error)
         else

lib/phoenix/plugs/router_logger.ex

@@ -1,5 +1,6 @@
 defmodule Phoenix.Plugs.RouterLogger do
   import Phoenix.Controller.Connection
+  require Logger
 
   @moduledoc """
   Plug to handle request logging at the router level
@@ -9,63 +10,16 @@ defmodule Phoenix.Plugs.RouterLogger do
 
   def init(opts), do: opts
 
-  def call(conn, level) do
-    before_stamp = :os.timestamp()
-    before = localtime_ms(before_stamp) |> format_time
-    if level == :debug do
-      IO.puts("#{before} #{conn.method}: #{inspect conn.path_info}")
-    end
-    case before_send(before_stamp, level) do
-      :none -> conn
-      fun -> Plug.Conn.register_before_send(conn, fun)
-    end
-  end
-
-  defp before_send(before_stamp, level) when level in [:debug, :info, :error] do
-    fn conn ->
-      {_, _, before_micro} = before_stamp
-      {_, _, after_micro} = :os.timestamp()
-      diff = after_micro - before_micro
-      before = localtime_ms(before_stamp) |> format_time
-
-      #if we micro gets too big then use ms
-      resp_time =  if diff > 1000 do
-        "#{div(diff, 1000)}ms"
-      else
-        "#{diff}µs"
-      end
-      log(level, before, resp_time, conn)
+  def call(conn, _level) do
+    Plug.Conn.register_before_send(conn, fn (conn) -> 
+      #Show the error message if they didn't process response type. Instead of blowing up.
+      {_status, content_type} = Phoenix.Controller.Connection.response_content_type(conn)
+      Logger.debug """
+      Processing by #{controller_module(conn)}.#{action_name(conn)}
+        Accept: #{content_type}
+        Parameters: #{inspect conn.params}
+      """
       conn
-    end
-  end
-  defp before_send(_, _), do: :none
-
-  defp log(:debug, _before, resp_time, conn) do
-    conn = Phoenix.Plugs.ContentTypeFetcher.fetch(conn)
-    IO.puts """
-        controller: #{controller_module(conn)}
-        action:     #{action_name(conn)}
-        accept:     #{response_content_type(conn)}
-        parameters: #{inspect conn.params}
-      resp_time=#{resp_time} status=#{conn.status} #{conn.method}
-    """
-  end
-
-  defp log(_level, before, resp_time, conn) do
-    IO.puts "#{before} resp_time=#{resp_time} status=#{conn.status} #{conn.method}: #{inspect conn.path_info}"
+    end)
   end
-
-  #Source https://gist.github.com/dergraf/2216802GOOGLE_PLACES
-  defp localtime_ms(now = {_, _, micro}) do
-    {date, {hours, minutes, meconds}} = :calendar.now_to_local_time(now)
-    {date, {hours, minutes, meconds, div(micro, 1000) |> rem(1000)}}
-  end
-
-  defp format_time({{yy, mm, dd}, {hh, mi, ss, ms}}) do
-    [pad(yy), ?-, pad(mm), ?-, pad(dd), ?\s, pad(hh), ?:, pad(mi), ?:, pad(ss), ?:, pad(ms)]
-  end
-
-  defp pad(int) when int < 10, do: [?0, Integer.to_string(int)]
-  defp pad(int), do: Integer.to_string(int)
-
 end

lib/phoenix/router.ex

@@ -15,6 +15,9 @@ defmodule Phoenix.Router do
       @before_compile unquote(__MODULE__)
       use Plug.Builder
 
+      plug Plug.Logger
+      plug Plugs.RouterLogger
+
       if Config.router(__MODULE__, [:static_assets]) do
         mount = Config.router(__MODULE__, [:static_assets_mount])
         plug Plug.Static, at: mount, from: Project.app
@@ -32,7 +35,6 @@ defmodule Phoenix.Router do
 
   defmacro __before_compile__(_env) do
     quote do
-      plug Plugs.RouterLogger, Config.get([:logger, :level])
       if Config.router(__MODULE__, [:code_reload]) do
         plug Plugs.CodeReloader
       end

mix.exs

@@ -5,7 +5,7 @@ defmodule Phoenix.Mixfile do
     [
       app: :phoenix,
       version: "0.3.1",
-      elixir: "~> 0.15.0",
+      elixir: "~> 0.15.1",
       deps: deps,
       package: [
         contributors: ["Chris McCord", "Darko Fabijan"],
@@ -22,14 +22,14 @@ defmodule Phoenix.Mixfile do
   def application do
     [
       mod: { Phoenix, [] },
-      applications: [:plug, :linguist, :inflex, :jazz]
+      applications: [:plug, :linguist, :inflex, :jazz, :logger]
     ]
   end
 
   def deps do
     [
       {:cowboy, "~> 1.0.0", optional: true},
-      {:plug, "0.5.3"},
+      {:plug, "0.6.0"},
       {:inflex, "0.2.4"},
       {:linguist, "~> 0.1.1"},
       {:jazz, "0.2.0"},

mix.lock

@@ -5,5 +5,5 @@
   "inflex": {:package, "0.2.4"},
   "jazz": {:package, "0.2.0"},
   "linguist": {:package, "0.1.1"},
-  "plug": {:package, "0.5.3"},
+  "plug": {:package, "0.6.0"},
   "ranch": {:package, "1.0.0"}}

template/config/config.exs

@@ -14,8 +14,10 @@ config :phoenix, <%= application_module %>.Router,
   session_key: "_<%= application_name %>_key",
   session_secret: "<%= session_secret %>"
 
-config :phoenix, :logger,
-  level: :error
+config :logger, :console,
+  format: "$time $metadata[$level] $message\n",
+  metadata: [:request_id]
+
 
 
 # Import environment specific config. Note, this must remain at the bottom of

template/config/dev.exs

@@ -10,7 +10,7 @@ config :phoenix, <%= application_module %>.Router,
   session_key: "_<%= application_name %>_key",
   session_secret: "<%= session_secret %>"
 
-config :phoenix, :logger,
+config :logger, :console
   level: :debug
 
 

template/config/prod.exs

@@ -9,6 +9,7 @@ config :phoenix, <%= application_module %>.Router,
   session_key: "_<%= application_name %>_key",
   session_secret: "<%= session_secret %>"
 
-config :phoenix, :logger,
-  level: :error
+config :logger, :console
+  level: :info
+  metadata: [:request_id] 
 

template/config/test.exs

@@ -9,7 +9,7 @@ config :phoenix, <%= application_module %>.Router,
   session_key: "_<%= application_name %>_key",
   session_secret: "<%= session_secret %>"
 
-config :phoenix, :logger,
+config :logger, :console
   level: :debug
 
 

template/mix.exs

@@ -4,7 +4,7 @@ defmodule <%= application_module %>.Mixfile do
   def project do
     [ app: :<%= application_name %>,
       version: "0.0.1",
-      elixir: "~> 0.15.0",
+      elixir: "~> 0.15.1",
       elixirc_paths: ["lib", "web"],
       deps: deps ]
   end
@@ -13,7 +13,7 @@ defmodule <%= application_module %>.Mixfile do
   def application do
     [
       mod: { <%= application_module %>, [] },
-      applications: [:phoenix, :cowboy]
+      applications: [:phoenix, :cowboy, :logger]
     ]
   end
 

test/phoenix/config_test.exs

@@ -47,7 +47,7 @@ defmodule Phoenix.Config.ConfigTest do
   end
 
   test "default/1 returns the default config value" do
-    assert Config.default([:logger, :level]) == :error
+    assert Config.default([:router, :port]) == 4000
   end
 
   test "default!/1 raises UndefinedConfigError if value is nil" do

test/phoenix/controller/connection_test.exs

@@ -24,22 +24,31 @@ defmodule Phoenix.Router.ConnectionTest do
     assert catch_throw(Connection.halt!(conn)) == {:halt, conn}
   end
 
-  test "response_content_type raises UnfetchedContentType error if unfetched" do
+  test "response_content_type! raises UnfetchedContentType error if unfetched" do
     assert_raise Errors.UnfetchedContentType, fn ->
-      Connection.response_content_type(%Conn{})
+      Connection.response_content_type!(%Conn{})
     end
   end
 
+  test "response_content_type returns :error if unfetched" do
+    assert {:error, _msg} = Connection.response_content_type(%Conn{})
+  end
+
+  test "response_content_type! returns content type when fetched" do
+    conn = Phoenix.Plugs.ContentTypeFetcher.fetch(%Conn{params: %{}})
+    assert Connection.response_content_type!(conn) == "text/html"
+  end
+
   test "response_content_type returns content type when fetched" do
     conn = Phoenix.Plugs.ContentTypeFetcher.fetch(%Conn{params: %{}})
-    assert Connection.response_content_type(conn) == "text/html"
+    assert Connection.response_content_type(conn) == {:ok, "text/html"}
   end
 
   test "response_content_type falls back to text/html when mime is invalid" do
     conn = Plugs.ContentTypeFetcher.fetch(
      %Conn{params: %{}, req_headers: [{"accept", "somethingcrazy/abc"}]}
     )
-    assert Connection.response_content_type(conn) == "text/html"
+    assert Connection.response_content_type!(conn) == "text/html"
   end
 
   test "assign_layout/2 assigns the private assign_layout" do