Add Logger

Makefile

@@ -68,7 +68,7 @@ erlang:
 # Since Mix depends on EEx and EEx depends on
 # Mix, we first compile EEx without the .app
 # file, then mix and then compile EEx fully
-elixir: stdlib lib/eex/ebin/Elixir.EEx.beam mix ex_unit eex iex
+elixir: stdlib lib/eex/ebin/Elixir.EEx.beam mix ex_unit logger eex iex
 
 stdlib: $(KERNEL) VERSION
 $(KERNEL): lib/elixir/lib/*.ex lib/elixir/lib/*/*.ex lib/elixir/lib/*/*/*.ex
@@ -90,6 +90,7 @@ $(UNICODE): lib/elixir/unicode/*
 	$(Q) cd lib/elixir && ../../$(ELIXIRC) unicode/unicode.ex -o ebin;
 
 $(eval $(call APP_TEMPLATE,ex_unit,ExUnit))
+$(eval $(call APP_TEMPLATE,logger,Logger))
 $(eval $(call APP_TEMPLATE,eex,EEx))
 $(eval $(call APP_TEMPLATE,mix,Mix))
 $(eval $(call APP_TEMPLATE,iex,IEx))
@@ -133,6 +134,7 @@ docs: compile ../ex_doc/bin/ex_doc
 	$(call DOCS,Mix,mix,Mix)
 	$(call DOCS,IEx,iex,IEx)
 	$(call DOCS,ExUnit,ex_unit,ExUnit)
+	$(call DOCS,ExUnit,logger,Logger)
 
 ../ex_doc/bin/ex_doc:
 	@ echo "ex_doc is not found in ../ex_doc as expected. See README for more information."
@@ -164,7 +166,7 @@ $(TEST_EBIN)/%.beam: $(TEST_ERL)/%.erl
 	$(Q) mkdir -p $(TEST_EBIN)
 	$(Q) $(ERLC) -o $(TEST_EBIN) $<
 
-test_elixir: test_stdlib test_ex_unit test_doc_test test_mix test_eex test_iex
+test_elixir: test_stdlib test_ex_unit test_logger test_doc_test test_mix test_eex test_iex
 
 test_doc_test: compile
 	@ echo "==> doctest (exunit)"

lib/elixir/src/elixir.erl

@@ -2,7 +2,7 @@
 %% private to the Elixir compiler and reserved to be used by Elixir only.
 -module(elixir).
 -behaviour(application).
--export([main/1, start_cli/0,
+-export([start_cli/0,
   string_to_quoted/4, 'string_to_quoted!'/4,
   env_for_eval/1, env_for_eval/2, quoted_to_erl/2, quoted_to_erl/3,
   eval/2, eval/3, eval_forms/3, eval_forms/4, eval_quoted/3]).
@@ -50,16 +50,16 @@ stop(_S) ->
 config_change(_Changed, _New, _Remove) ->
   ok.
 
-%% escript entry point
-
-main(Args) ->
-  {ok, _} = application:ensure_all_started(?MODULE),
-  'Elixir.Kernel.CLI':main(Args).
-
 %% Boot and process given options. Invoked by Elixir's script.
 
 start_cli() ->
   {ok, _} = application:ensure_all_started(?MODULE),
+  %% We start the Logger so tools that depend on Elixir
+  %% always have the Logger directly accessible. However
+  %% Logger is not a dependency of the Elixir application,
+  %% which means releases that want to use Logger must
+  %% always list it as part of its applications.
+  _ = application:start(logger),
   'Elixir.Kernel.CLI':main(init:get_plain_arguments()).
 
 %% EVAL HOOKS

lib/logger/lib/logger.ex

@@ -0,0 +1,464 @@
+defmodule Logger do
+  use Application
+
+  @moduledoc ~S"""
+  A logger for Elixir applications.
+
+  It includes many features:
+
+    * Provides debug, info, warn and error levels.
+
+    * Supports multiple backends which are automatically
+      supervised when plugged into Logger.
+
+    * Formats and truncates messages on the client
+      to avoid clogging logger backends.
+
+    * Alternates between sync and async modes to keep
+      it performant when required but also apply back-
+      pressure when under stress.
+
+    * Wraps OTP's error_logger to avoid it from
+      overflowing.
+
+  ## Levels
+
+  The supported levels are:
+
+    * `:debug` - for debug-related messages
+    * `:info` - for information of any kind
+    * `:warn` - for warnings
+    * `:error` - for errors
+
+  ## Configuration
+
+  Logger supports a wide range of configuration.
+
+  This configuration is split in three categories:
+
+    * Application configuration - must be set before the logger
+      application is started
+
+    * Runtime configuration - can be set before the logger
+      application is started but changed during runtime
+
+    * Error logger configuration - configuration for the
+      wrapper around OTP's error_logger
+
+  ### Application configuration
+
+  The following configuration must be set via config files
+  before the logger application is started.
+
+    * `:backends` - the backends to be used. Defaults to `[:console]`.
+      See the "Backends" section for more information.
+
+    * `:compile_time_purge_level` - purge all calls that have log level
+      lower than the configured value at compilation time. This means the
+      Logger call will be completely removed at compile time, occuring
+      no overhead at runtime. By default, defaults to `:debug` and only
+      applies to the `Logger.debug`, `Logger.info`, etc style of calls.
+
+  ### Runtime Configuration
+
+  All configuration below can be set via the config files but also
+  changed dynamically during runtime via `Logger.configure/1`.
+
+    * `:level` - the logging level. Attempting to log any message
+      with severity less than the configured level will simply
+      cause the message to be ignored. Keep in mind that each backend
+      may have its specific level too.
+
+    * `:utc_log` - when true, uses UTC in logs. By default it uses
+      local time (i.e. it defaults to false).
+
+    * `:truncate` - the maximum message size to be logged. Defaults
+      to 8192 bytes. Note this configuration is approximate. Truncated
+      messages will have " (truncated)" at the end.
+
+    * `:sync_threshold` - if the logger manager has more than
+      `sync_threshold` messages in its queue, logger will change
+      to sync mode, to apply back-pressure to the clients.
+      Logger will return to sync mode once the number of messages
+      in the queue reduce to `sync_threshold * 0.75` messages.
+      Defaults to 20 messages.
+
+  ### Error logger configuration
+
+  The following configuration applies to the Logger wrapper around
+  Erlang's error_logger. All the configurations below must be set
+  before the logger application starts.
+
+    * `:handle_otp_reports` - redirects OTP reports to Logger so
+      they are formatted in Elixir terms. This uninstalls Erlang's
+      logger that prints terms to terminal.
+
+    * `:discard_threshold_for_error_logger` - a value that, when
+      reached, triggers the error logger to discard messages. This
+      value must be a positive number that represents the maximum
+      number of messages accepted per second. Once above this
+      threshold, the error_logger enters in discard mode for the
+      remaining of that second. Defaults to 500 messages.
+
+  Furthermore, Logger allows messages sent by Erlang's `error_logger`
+  to be translated into an Elixir format via translators. Translator
+  can be dynamically added at any time with the `add_translator/1`
+  and `remove_translator/1` APIs. Check `Logger.Translator` for more
+  information.
+
+  ## Backends
+
+  Logger supports different backends where log messages are written to.
+
+  The available backends by default are:
+
+    * `:console` - Logs messages to the console (enabled by default)
+
+  Developers may also implement their own backends, an option that
+  is explored with detail below.
+
+  The initial backends are loaded via the `:backends` configuration,
+  which must be set before the logger application is started. However,
+  backends can be added or removed dynamically via the `add_backend/2`,
+  `remove_backend/1` and `configure_backend/2` functions. Note though
+  that dynamically added backends are not restarded in case of crashes.
+
+  ### Console backend
+
+  The console backend logs message to the console. It supports the
+  following options:
+
+    * `:level` - the level to be logged by this backend.
+      Note though messages are first filtered by the general
+      `:level` configuration in `:logger`
+
+    * `:format` - the format message used to print logs.
+      Defaults to: "$time $metadata[$level] $message\n"
+
+    * `:metadata` - the metadata to be printed by `$metadata`.
+      Defaults to an empty list (no metadata)
+
+  Here is an example on how to configure the `:console` in a
+  `config/config.exs` file:
+
+      config :logger, :console,
+        format: "$date $time [$level] $metadata$message\n",
+        metadata: [:user_id]
+
+  You can read more about formatting in `Logger.Formatter`.
+
+  ### Custom backends
+
+  Any developer can create their own backend for Logger.
+  Since Logger is an event manager powered by `GenEvent`,
+  writing a new backend is a matter of creating an event
+  handler, as described in the `GenEvent` module.
+
+  From now on, we will be using event handler to refer to
+  your custom backend, as we head into implementation details.
+
+  The `add_backend/1` function is used to start a new
+  backend, which installs the given event handler to the
+  Logger event manager. This event handler is automatically
+  supervised by Logger.
+
+  Once added, the handler should be able to handle events
+  in the following format:
+
+      {level, group_leader,
+        {Logger, message, timestamp, metadata}}
+
+  The level is one of `:error`, `:info`, `:warn` or `:error`,
+  as previously described, the group leader is the group
+  leader of the process who logged the message, followed by
+  a tuple starting with the atom `Logger`, the message as
+  iodata, the timestamp and a keyword list of metadata.
+
+  It is recommended that handlers ignore messages where
+  the group leader is in a different node than the one
+  the handler is installed.
+
+  Furthermore, backends can be configured via the `configure_backend/2`
+  function which requires event handlers to handle calls of
+  the following format:
+
+      {:configure, options}
+
+  where options is a keyword list. The result of the call is
+  the result returned by `configure_backend/2`. You may simply
+  return `:ok` if you don't perform any kind of validation.
+
+  It is recommended that backends support at least the following
+  configuration values:
+
+    * level - the logging level for that backend
+    * format - the logging format for that backend
+    * metadata - the metadata to include the backend
+
+  Check the implementation for `Logger.Backends.Console` for
+  examples on how to handle the recommendations in this section
+  and how to process the existing options.
+  """
+
+  @type backend :: GenEvent.handler
+  @type level :: :error | :info | :warn | :debug
+  @levels [:error, :info, :warn, :debug]
+
+  @doc false
+  def start(_type, _args) do
+    import Supervisor.Spec
+
+    otp_reports? = Application.get_env(:logger, :handle_otp_reports)
+    threshold    = Application.get_env(:logger, :discard_threshold_for_error_logger)
+
+    handlers =
+      for backend <- Application.get_env(:logger, :backends) do
+        {Logger, translate_backend(backend), []}
+      end
+
+    options  = [strategy: :rest_for_one, name: Logger.Supervisor]
+    children = [worker(GenEvent, [[name: Logger]]),
+                worker(Logger.Watcher, [Logger, Logger.Config, []],
+                  [id: Logger.Config, function: :watcher]),
+                supervisor(Logger.Watcher, [handlers]),
+                worker(Logger.Watcher,
+                  [:error_logger, Logger.ErrorHandler, {otp_reports?, threshold}],
+                  [id: Logger.ErrorHandler, function: :watcher])]
+
+    case Supervisor.start_link(children, options) do
+      {:ok, _} = ok ->
+        deleted = delete_error_logger_handler(otp_reports?, :error_logger_tty_h, [])
+        store_deleted_handlers(deleted)
+        ok
+      {:error, _} = error ->
+        error
+    end
+  end
+
+  @doc false
+  def stop(_) do
+    Application.get_env(:logger, :deleted_handlers)
+    |> Enum.each(&:error_logger.add_report_handler/1)
+
+    # We need to do this in another process as the Application
+    # Controller is currently blocked shutting down this app.
+    spawn_link(fn -> Logger.Config.clear_data end)
+
+    :ok
+  end
+
+  defp store_deleted_handlers(list) do
+    Application.put_env(:logger, :deleted_handlers, Enum.into(list, HashSet.new))
+  end
+
+  defp delete_error_logger_handler(should_delete?, handler, deleted) do
+    if should_delete? and
+         :error_logger.delete_report_handler(handler) != {:error, :module_not_found} do
+      [handler|deleted]
+    else
+      deleted
+    end
+  end
+
+  @metadata :logger_metadata
+
+  @doc """
+  Adds the given keyword list to the current process metadata.
+  """
+  def metadata(dict) do
+    Process.put(@metadata, dict ++ metadata)
+  end
+
+  @doc """
+  Reads the current process metadata.
+  """
+  def metadata() do
+    Process.get(@metadata) || []
+  end
+
+  @doc """
+  Retrieves the logger level.
+
+  The logger level can be changed via `configure/1`.
+  """
+  @spec level() :: level
+  def level() do
+    check_logger!
+    %{level: level} = Logger.Config.__data__
+    level
+  end
+
+  @doc """
+  Compare log levels.
+
+  Receives to log levels and compares the `left`
+  against `right` and returns `:lt`, `:eq` or `:gt`.
+  """
+  @spec compare_levels(level, level) :: :lt | :eq | :gt
+  def compare_levels(level, level), do:
+    :eq
+  def compare_levels(left, right), do:
+    if(level_to_number(left) > level_to_number(right), do: :gt, else: :lt)
+
+  defp level_to_number(:debug), do: 0
+  defp level_to_number(:info),  do: 1
+  defp level_to_number(:warn),  do: 2
+  defp level_to_number(:error), do: 3
+
+  @doc """
+  Configures the logger.
+
+  See the "Runtime Configuration" section in `Logger` module
+  documentation for the available options.
+  """
+  @valid_options [:compile_time_purge_level, :sync_threshold, :truncate, :level, :utc_log]
+
+  def configure(options) do
+    Logger.Config.configure(Dict.take(options, @valid_options))
+  end
+
+  @doc """
+  Adds a new backend.
+  """
+  def add_backend(backend) do
+    Logger.Watcher.watch(Logger, translate_backend(backend), [])
+  end
+
+  @doc """
+  Removes a backend.
+  """
+  def remove_backend(backend) do
+    Logger.Watcher.unwatch(Logger, translate_backend(backend))
+  end
+
+  @doc """
+  Adds a new translator.
+  """
+  def add_translator({mod, fun} = translator) when is_atom(mod) and is_atom(fun) do
+    Logger.Config.add_translator(translator)
+  end
+
+  @doc """
+  Removes a translator.
+  """
+  def remove_translator({mod, fun} = translator) when is_atom(mod) and is_atom(fun) do
+    Logger.Config.remove_translator(translator)
+  end
+
+  @doc """
+  Configures the given backend.
+  """
+  @spec configure_backend(backend, Keywowrd.t) :: term
+  def configure_backend(backend, options) when is_list(options) do
+    GenEvent.call(Logger, translate_backend(backend), {:configure, options})
+  end
+
+  defp translate_backend(:console), do: Logger.Backends.Console
+  defp translate_backend(other),    do: other
+
+  @doc """
+  Logs a message.
+
+  Developers should rather use the macros `Logger.debug/2`,
+  `Logger.warn/2`, `Logger.info/2` or `Logger.error/2` instead
+  of this function as they automatically include caller metadata
+  and can eliminate the Logger call altogether at compile time if
+  desired.
+
+  Use this function only when there is a need to log dynamically
+  or you want to explicitly avoid embedding metadata.
+  """
+  @spec log(level, IO.chardata | (() -> IO.chardata), Keyword.t) :: :ok
+  def log(level, chardata, metadata \\ []) when level in @levels and is_list(metadata) do
+    check_logger!
+    %{mode: mode, truncate: truncate,
+      level: min_level, utc_log: utc_log?} = Logger.Config.__data__
+
+    if compare_levels(level, min_level) != :lt do
+      tuple = {Logger, truncate(chardata, truncate), Logger.Utils.timestamp(utc_log?),
+               [pid: self()] ++ metadata() ++ metadata}
+      notify(mode, {level, Process.group_leader(), tuple})
+    end
+
+    :ok
+  end
+
+  @doc """
+  Logs a warning.
+
+  ## Examples
+
+      Logger.warn "knob turned too much to the right"
+      Logger.warn fn -> "expensive to calculate warning" end
+
+  """
+  defmacro warn(chardata, metadata \\ []) do
+    macro_log(:warn, chardata, metadata, __CALLER__)
+  end
+
+  @doc """
+  Logs some info.
+
+  ## Examples
+
+      Logger.info "mission accomplished"
+      Logger.info fn -> "expensive to calculate info" end
+
+  """
+  defmacro info(chardata, metadata \\ []) do
+    macro_log(:info, chardata, metadata, __CALLER__)
+  end
+
+  @doc """
+  Logs an error.
+
+  ## Examples
+
+      Logger.error "oops"
+      Logger.error fn -> "expensive to calculate error" end
+
+  """
+  defmacro error(chardata, metadata \\ []) do
+    macro_log(:error, chardata, metadata, __CALLER__)
+  end
+
+  @doc """
+  Logs a debug message.
+
+  ## Examples
+
+      Logger.debug "hello?"
+      Logger.debug fn -> "expensive to calculate debug" end
+
+  """
+  defmacro debug(chardata, metadata \\ []) do
+    macro_log(:debug, chardata, metadata, __CALLER__)
+  end
+
+  defp macro_log(level, chardata, metadata, caller) do
+    min_level = Application.get_env(:logger, :compile_time_purge_level, :debug)
+    if compare_levels(level, min_level) != :lt do
+      %{module: module, function: function, line: line} = caller
+      caller = [module: module, function: function, line: line]
+      quote do
+        Logger.log(unquote(level), unquote(chardata), unquote(caller) ++ unquote(metadata))
+      end
+    else
+      :ok
+    end
+  end
+
+  defp truncate(data, n) when is_function(data, 0),
+    do: Logger.Utils.truncate(data.(), n)
+  defp truncate(data, n) when is_list(data) or is_binary(data),
+    do: Logger.Utils.truncate(data, n)
+
+  defp notify(:sync, msg),  do: GenEvent.sync_notify(Logger, msg)
+  defp notify(:async, msg), do: GenEvent.notify(Logger, msg)
+
+  defp check_logger! do
+    unless Process.whereis(Logger) do
+      raise "Cannot log messages, the :logger application is not running"
+    end
+  end
+end

lib/logger/lib/logger/backends/console.ex

@@ -0,0 +1,47 @@
+defmodule Logger.Backends.Console do
+  use GenEvent
+
+  def init(_) do
+    if user = Process.whereis(:user) do
+      Process.group_leader(self(), user)
+      {:ok, configure([])}
+    else
+      {:error, :ignore}
+    end
+  end
+
+  def handle_call({:configure, options}, _state) do
+    {:ok, :ok, configure(options)}
+  end
+
+  def handle_event({_level, gl, _event}, state) when node(gl) != node() do
+    {:ok, state}
+  end
+
+  def handle_event({level, _gl, {Logger, msg, ts, md}}, %{level: min_level} = state) do
+    if nil?(min_level) or Logger.compare_levels(level, min_level) != :lt do
+      log_event(level, msg, ts, md, state)
+    end
+    {:ok, state}
+  end
+
+  ## Helpers
+
+  defp configure(options) do
+    console = Keyword.merge(Application.get_env(:logger, :console, []), options)
+    Application.put_env(:logger, :console, console)
+
+    format = console
+      |> Keyword.get(:format)
+      |> Logger.Formatter.compile
+
+    level    = Keyword.get(console, :level)
+    metadata = Keyword.get(console, :metadata, [])
+    %{format: format, metadata: metadata, level: level}
+  end
+
+  defp log_event(level, msg, ts, md, %{format: format, metadata: metadata}) do
+    :io.put_chars :user,
+      Logger.Formatter.format(format, level, msg, ts, Dict.take(md, metadata))
+  end
+end

lib/logger/lib/logger/config.ex

@@ -0,0 +1,117 @@
+defmodule Logger.Config do
+  @moduledoc false
+
+  use GenEvent
+
+  @name __MODULE__
+  @data :__data__
+
+  def start_link do
+    GenServer.start_link(__MODULE__, :ok, name: @name)
+  end
+
+  def configure(options) do
+    GenEvent.call(Logger, @name, {:configure, options})
+  end
+
+  def add_translator(translator) do
+    GenEvent.call(Logger, @name, {:add_translator, translator})
+  end
+
+  def remove_translator(translator) do
+    GenEvent.call(Logger, @name, {:remove_translator, translator})
+  end
+
+  def __data__() do
+    Application.get_env(:logger, @data)
+  end
+
+  def clear_data() do
+    Application.delete_env(:logger, @data)
+  end
+
+  def restart do
+    set = Application.get_env(:logger, :deleted_handlers)
+    Application.put_env(:logger, :deleted_handlers, HashSet.new)
+    Application.stop(:logger)
+    Enum.each(set, &:error_logger.add_report_handler/1)
+    Application.start(:logger)
+  end
+
+  ## Callbacks
+
+  def init(_) do
+    # Use previous data if available in case this handler crashed.
+    state = __data__ || compute_state(:async)
+    {:ok, state}
+  end
+
+  def handle_event({_type, gl, _msg} = event, state) when node(gl) != node() do
+    # Cross node messages are always async which also
+    # means this handler won't crash in case there is
+    # no logger installed in the other node.
+    GenEvent.notify({Logger, node(gl)}, event)
+    {:ok, state}
+  end
+
+  def handle_event(_event, state) do
+    {:message_queue_len, len} = Process.info(self(), :message_queue_len)
+
+    cond do
+      len > state.sync_threshold and state.mode == :async ->
+        state = %{state | mode: :sync}
+        persist(state)
+        {:ok, state}
+      len < state.async_threshold and state.mode == :sync ->
+        state = %{state | mode: :async}
+        persist(state)
+        {:ok, state}
+      true ->
+        {:ok, state}
+    end
+  end
+
+  def handle_call({:configure, options}, state) do
+    Enum.each options, fn {key, value} ->
+      Application.put_env(:logger, key, value)
+    end
+    {:ok, :ok, compute_state(state.mode)}
+  end
+
+  def handle_call({:add_translator, translator}, state) do
+    state = update_translators(state, fn t -> [translator|List.delete(t, translator)] end)
+    {:ok, :ok, state}
+  end
+
+  def handle_call({:remove_translator, translator}, state) do
+    state = update_translators(state, &List.delete(&1, translator))
+    {:ok, :ok, state}
+  end
+
+  ## Helpers
+
+  defp update_translators(%{translators: translators} = state, fun) do
+    translators = fun.(translators)
+    Application.put_env(:logger, :translators, translators)
+    persist %{state | translators: translators}
+  end
+
+  defp compute_state(mode) do
+    level       = Application.get_env(:logger, :level)
+    utc_log     = Application.get_env(:logger, :utc_log)
+    truncate    = Application.get_env(:logger, :truncate)
+    translators = Application.get_env(:logger, :translators)
+
+    sync_threshold  = Application.get_env(:logger, :sync_threshold)
+    async_threshold = trunc(sync_threshold * 0.75)
+
+    persist %{level: level, mode: mode, truncate: truncate,
+              utc_log: utc_log, sync_threshold: sync_threshold,
+              async_threshold: async_threshold, translators: translators}
+  end
+
+  defp persist(state) do
+    Application.put_env(:logger, @data, state)
+    state
+  end
+end

lib/logger/lib/logger/error_handler.ex

@@ -0,0 +1,117 @@
+defmodule Logger.ErrorHandler do
+  use GenEvent
+
+  require Logger
+
+  def init({otp?, threshold}) do
+    {:ok, %{otp: otp?, threshold: threshold,
+            last_length: 0, last_time: :os.timestamp, dropped: 0}}
+  end
+
+  ## Handle event
+
+  def handle_event({_type, gl, _msg}, state) when node(gl) != node() do
+    {:ok, state}
+  end
+
+  def handle_event(event, state) do
+    state = check_threshold(state)
+    log_event(event, state)
+    {:ok, state}
+  end
+
+  ## Helpers
+
+  defp log_event({:error, _gl, {pid, format, data}}, %{otp: true}),
+    do: log_event(:error, :format, pid, {format, data})
+  defp log_event({:error_report, _gl, {pid, :std_error, format}}, %{otp: true}),
+    do: log_event(:error, :report, pid, {:std_error, format})
+
+  defp log_event({:warning_msg, _gl, {pid, format, data}}, %{otp: true}),
+    do: log_event(:warn, :format, pid, {format, data})
+  defp log_event({:warning_report, _gl, {pid, :std_warning, format}}, %{otp: true}),
+    do: log_event(:warn, :report, pid, {:std_warning, format})
+
+  defp log_event({:info_msg, _gl, {pid, format, data}}, %{otp: true}),
+    do: log_event(:info, :format, pid, {format, data})
+  defp log_event({:info_report, _gl, {pid, :std_info, format}}, %{otp: true}),
+    do: log_event(:info, :report, pid, {:std_info, format})
+
+  defp log_event(_, _state),
+    do: :ok
+
+  defp log_event(level, kind, pid, data) do
+    %{level: min_level, truncate: truncate,
+      utc_log: utc_log?, translators: translators} = Logger.Config.__data__
+
+    if Logger.compare_levels(level, min_level) != :lt &&
+       (message = translate(translators, min_level, level, kind, data, truncate)) do
+      message = Logger.Utils.truncate(message, truncate)
+
+      # Mode is always async to avoid clogging the error_logger
+      GenEvent.notify(Logger,
+        {level, Process.group_leader(),
+          {Logger, message, Logger.Utils.timestamp(utc_log?), [pid: ensure_pid(pid)]}})
+    end
+
+    :ok
+  end
+
+  defp ensure_pid(pid) when is_pid(pid), do: pid
+  defp ensure_pid(_), do: self()
+
+  defp check_threshold(%{last_time: last_time, last_length: last_length,
+                         dropped: dropped, threshold: threshold} = state) do
+    {m, s, _} = current_time = :os.timestamp
+    current_length = message_queue_length()
+
+    cond do
+      match?({^m, ^s, _}, last_time) and current_length - last_length > threshold ->
+        count = drop_messages(current_time, 0)
+        %{state | dropped: dropped + count, last_length: message_queue_length()}
+      match?({^m, ^s, _}, last_time) ->
+        state
+      true ->
+        if dropped > 0 do
+          Logger.warn "Logger dropped #{dropped} OTP/SASL messages as it " <>
+                      "exceeded the amount of #{threshold} messages/second"
+        end
+        %{state | dropped: 0, last_time: current_time, last_length: current_length}
+    end
+  end
+
+  defp message_queue_length() do
+    {:message_queue_len, len} = Process.info(self(), :message_queue_len)
+    len
+  end
+
+  defp drop_messages({m, s, _} = last_time, count) do
+    case :os.timestamp do
+      {^m, ^s, _} ->
+        receive do
+          {:notify, _event} -> drop_messages(last_time, count + 1)
+        after
+          0 -> count
+        end
+      _ ->
+        count
+    end
+  end
+
+  defp translate([{mod, fun}|t], min_level, level, kind, data, truncate) do
+    case apply(mod, fun, [min_level, level, kind, data]) do
+      {:ok, iodata} -> iodata
+      :skip -> nil
+      :none -> translate(t, min_level, level, kind, data, truncate)
+    end
+  end
+
+  defp translate([], _min_level, _level, :format, {format, args}, truncate) do
+    {format, args} = Logger.Utils.inspect(format, args, truncate)
+    :io_lib.format(format, args)
+  end
+
+  defp translate([], _min_level, _level, :report, {_type, data}, _truncate) do
+    Kernel.inspect(data)
+  end
+end

lib/logger/lib/logger/formatter.ex

@@ -0,0 +1,112 @@
+import Kernel, except: [inspect: 2]
+
+defmodule Logger.Formatter do
+  @moduledoc ~S"""
+  Conveniences for formatting data for logs.
+
+  This module allows developers to specify a string that
+  serves as template for log messages, for example:
+
+      $time $metadata[$level] $message\n
+
+  Will print error messages as:
+
+      18:43:12.439 user_id=13 [error] Hello\n
+
+  The valid parameters you can use are:
+
+    * `$time` - time the log message was sent
+    * `$date` - date the log message was sent
+    * `$message` - the log message
+    * `$level` - the log level
+    * `$node` - the node that prints the message
+    * `$metadata` - user controled data presented in "key=val key2=val2" format
+
+  Backends typically allow developers to supply such control
+  strings via configuration files. This module provides `compile/1`,
+  which compiles the string into a format for fast operations at
+  runtime and `format/5` to format the compiled pattern into an
+  actual IO data.
+
+  ## Metadata
+
+  Metadata to be sent to the Logger can be read and written with
+  the `Logger.metadata/0` and `Logger.metadata/1` functions. For example,
+  you can set `Logger.metadata([user_id: 13])` to add user_id metadata
+  to the current process. The user can configure the backend to chose
+  which metadata it wants to print and it will replace the $metadata
+  value.
+  """
+
+  @valid_patterns [:time, :date, :message, :level, :node, :metadata]
+  @default_pattern "$time $metadata[$level] $message\n"
+
+  @doc ~S"""
+  Compiles a format string into an array that the `format/5` can handle.
+
+  The valid parameters you can use are:
+
+  * $time
+  * $date
+  * $message
+  * $level
+  * $node
+  * $metadata - metadata is presented in key=val key2=val2 format.
+
+  If you pass nil into compile it will use the default
+  format of `$time $metadata [$level] $message`
+
+  If you would like to make your own custom formatter simply pass
+  `{module, function}` to compile and the rest is handled.
+
+      iex> Logger.Formatter.compile("$time $metadata [$level] $message\n")
+      [:time, " ", :metadata, " [", :level, "] ", :message, "\n"]
+  """
+  @spec compile(binary | nil) :: list()
+  @spec compile({atom, atom}) :: {atom, atom}
+
+  def compile(nil), do: compile(@default_pattern)
+  def compile({mod, fun}) when is_atom(mod) and is_atom(fun), do: {mod, fun}
+
+  def compile(str) do
+    for part <- Regex.split(~r/(?<head>)\$[a-z]+(?<tail>)/, str, on: [:head, :tail], trim: true) do
+      case part do
+        "$" <> code -> compile_code(String.to_atom(code))
+        _           -> part
+      end
+    end
+  end
+
+  defp compile_code(key) when key in @valid_patterns, do: key
+  defp compile_code(key) when is_atom(key) do
+    raise(ArgumentError, message: "$#{key} is an invalid format pattern.")
+  end
+
+  @doc """
+  Takes a compiled format and injects the, level, timestamp, message and
+  metadata listdict and returns a properly formatted string.
+  """
+
+  def format({mod, fun}, level, msg, ts, md) do
+    Module.function(mod, fun, 4).(level, msg, ts, md)
+  end
+
+  def format(config, level, msg, ts, md) do
+    for c <- config do
+      output(c, level, msg, ts, md)
+    end
+  end
+
+  defp output(:message, _, msg, _, _),        do: msg
+  defp output(:date, _, _, {date, _time}, _), do: Logger.Utils.format_date(date)
+  defp output(:time, _, _, {_date, time}, _), do: Logger.Utils.format_time(time)
+  defp output(:level, level, _, _, _),        do: Atom.to_string(level)
+  defp output(:node, _, _, _, _),             do: Atom.to_string(node())
+  defp output(:metadata, _, _, _, []),        do: ""
+  defp output(:metadata, _, _, _, meta) do
+    Enum.map(meta, fn {key, val} ->
+      [to_string(key), ?=, to_string(val), ?\s]
+    end)
+  end
+  defp output(other, _, _, _, _), do: other
+end

lib/logger/lib/logger/translator.ex

@@ -0,0 +1,69 @@
+defmodule Logger.Translator do
+  @moduledoc """
+  Default translation for Erlang log messages.
+
+  Logger allows developers to rewrite log messages provided by
+  Erlang applications into a format more compatible to Elixir
+  log messages by providing translator.
+
+  A translator is simply a tuple containing a module and a function
+  that can be added and removed via the `add_translator/1` and
+  `remove_translator/1` functions and is invoked for every Erlang
+  message above the minimum log level with four arguments:
+
+    * `min_level` - the current Logger level
+    * `level` - the level of the message being translator
+    * `kind` - if the message is a report or a format
+    * `data` - the data to format. If it is a report, it is a tuple
+      with `{report_type, report_data}`, if it is a format, it is a
+      tuple with `{format_message, format_args}`
+
+  The function must return:
+
+    * `{:ok, iodata}` - if the message was translated with its translation
+    * `:skip` - if the message is not meant to be translated nor logged
+    * `:none` - if there is no translation, which triggers the next translator
+
+  See the function `translate/4` in this module for an example implementation
+  and the default messages translated by Logger.
+  """
+
+  def translate(min_level, :error, :format, message) do
+    case message do
+      {'** Generic server ' ++ _, [name, last, state, reason]} ->
+        msg = "GenServer #{inspect name} terminating\n"
+        if min_level == :debug do
+          msg = msg <> "Last message: #{inspect last}\n"
+                    <> "State: #{inspect state}\n"
+        end
+        {:ok, msg <> "** (exit) " <> Exception.format_exit(reason)}
+
+      {'** gen_event handler ' ++ _, [name, manager, last, state, reason]} ->
+        msg = "GenEvent handler #{inspect name} installed in #{inspect manager} terminating\n"
+        if min_level == :debug do
+          msg = msg <> "Last message: #{inspect last}\n"
+                    <> "State: #{inspect state}\n"
+        end
+        {:ok, msg <> "** (exit) " <> Exception.format_exit(reason)}
+
+      {'** Task ' ++ _, [name, starter, function, args, reason]} ->
+        msg = "Task #{inspect name} started from #{inspect starter} terminating\n" <>
+              "Function: #{inspect function}\n" <>
+              "    Args: #{inspect args}\n" <>
+              "** (exit) " <> Exception.format_exit(reason)
+        {:ok, msg}
+
+      _ ->
+        :none
+    end
+  end
+
+  def translate(_min_level, :info, :report,
+                {:std_info, [application: app, exited: reason, type: _type]}) do
+    {:ok, "Application #{app} exited with reason #{Exception.format_exit(reason)}"}
+  end
+
+  def translate(_min_level, _level, _kind, _message) do
+    :none
+  end
+end

lib/logger/lib/logger/utils.ex

@@ -0,0 +1,267 @@
+defmodule Logger.Utils do
+  @moduledoc false
+
+  @doc """
+  Truncates a char data into n bytes.
+
+  There is a chance we truncate in the middle of a grapheme
+  cluster but we never truncate in the middle of a binary
+  codepoint. For this reason, truncation is not exact.
+  """
+  @spec truncate(IO.chardata, non_neg_integer) :: IO.chardata
+  def truncate(chardata, n) when n >= 0 do
+    {chardata, n} = truncate_n(chardata, n)
+    if n >= 0, do: chardata, else: [chardata, " (truncated)"]
+  end
+
+  defp truncate_n(_, n) when n < 0 do
+    {"", n}
+  end
+
+  defp truncate_n(binary, n) when is_binary(binary) do
+    remaining = n - byte_size(binary)
+    if remaining < 0 do
+      # There is a chance we are cutting at the wrong
+      # place so we need to fix the binary.
+      {fix_binary(binary_part(binary, 0, n)), remaining}
+    else
+      {binary, remaining}
+    end
+  end
+
+  defp truncate_n(int, n) when int in 0..127,                      do: {int, n-1}
+  defp truncate_n(int, n) when int in 127..0x07FF,                 do: {int, n-2}
+  defp truncate_n(int, n) when int in 0x800..0xFFFF,               do: {int, n-3}
+  defp truncate_n(int, n) when int >= 0x10000 and is_integer(int), do: {int, n-4}
+
+  defp truncate_n(list, n) when is_list(list) do
+    truncate_n_list(list, n, [])
+  end
+
+  defp truncate_n_list(_, n, acc) when n < 0 do
+    {:lists.reverse(acc), n}
+  end
+
+  defp truncate_n_list([h|t], n, acc) do
+    {h, n} = truncate_n(h, n)
+    truncate_n_list(t, n, [h|acc])
+  end
+
+  defp truncate_n_list([], n, acc) do
+    {:lists.reverse(acc), n}
+  end
+
+  defp truncate_n_list(t, n, acc) do
+    {t, n} = truncate_n(t, n)
+    {:lists.reverse(acc, t), n}
+  end
+
+  defp fix_binary(binary) do
+    # Use a thirteen-bytes offset to look back in the binary.
+    # This should allow at least two codepoints of 6 bytes.
+    suffix_size = min(byte_size(binary), 13)
+    prefix_size = byte_size(binary) - suffix_size
+    <<prefix :: binary-size(prefix_size), suffix :: binary-size(suffix_size)>> = binary
+    prefix <> fix_binary(suffix, "")
+  end
+
+  defp fix_binary(<<h::utf8, t::binary>>, acc) do
+    acc <> <<h::utf8>> <> fix_binary(t, "")
+  end
+
+  defp fix_binary(<<h, t::binary>>, acc) do
+    fix_binary(t, <<h, acc::binary>>)
+  end
+
+  defp fix_binary(<<>>, _acc) do
+    <<>>
+  end
+
+  @doc """
+  Receives a format string and arguments and replace `~p`,
+  `~P`, `~w` and `~W` by its inspected variants.
+  """
+  def inspect(format, args, truncate, opts \\ %Inspect.Opts{})
+
+  def inspect(format, args, truncate, opts) when is_atom(format) do
+    do_inspect(Atom.to_char_list(format), args, truncate, opts)
+  end
+
+  def inspect(format, args, truncate, opts) when is_binary(format) do
+    do_inspect(:binary.bin_to_list(format), args, truncate, opts)
+  end
+
+  def inspect(format, args, truncate, opts) when is_list(format) do
+    do_inspect(format, args, truncate, opts)
+  end
+
+  defp do_inspect(format, [], _truncate, _opts), do: {format, []}
+  defp do_inspect(format, args, truncate, opts) do
+    # A pre-pass that removes binaries from
+    # arguments according to the truncate limit.
+    {args, _} = Enum.map_reduce(args, truncate, fn arg, acc ->
+      if is_binary(arg) do
+        truncate_n(arg, acc)
+      else
+        {arg, acc}
+      end
+    end)
+    do_inspect(format, args, [], [], opts)
+  end
+
+  defp do_inspect([?~|t], args, used_format, used_args, opts) do
+    {t, args, cc_format, cc_args} = collect_cc(:width, t, args, [?~], [], opts)
+    do_inspect(t, args, cc_format ++ used_format, cc_args ++ used_args, opts)
+  end
+
+  defp do_inspect([h|t], args, used_format, used_args, opts),
+    do: do_inspect(t, args, [h|used_format], used_args, opts)
+
+  defp do_inspect([], [], used_format, used_args, _opts),
+    do: {:lists.reverse(used_format), :lists.reverse(used_args)}
+
+  ## width
+
+  defp collect_cc(:width, [?-|t], args, used_format, used_args, opts),
+    do: collect_value(:width, t, args, [?-|used_format], used_args, opts, :precision)
+
+  defp collect_cc(:width, t, args, used_format, used_args, opts),
+    do: collect_value(:width, t, args, used_format, used_args, opts, :precision)
+
+  ## precision
+
+  defp collect_cc(:precision, [?.|t], args, used_format, used_args, opts),
+    do: collect_value(:precision, t, args, [?.|used_format], used_args, opts, :pad_char)
+
+  defp collect_cc(:precision, t, args, used_format, used_args, opts),
+    do: collect_cc(:pad_char, t, args, used_format, used_args, opts)
+
+  ## pad char
+
+  defp collect_cc(:pad_char, [?.,?*|t], [arg|args], used_format, used_args, opts),
+    do: collect_cc(:encoding, t, args, [?*,?.|used_format], [arg|used_args], opts)
+
+  defp collect_cc(:pad_char, [?.,p|t], args, used_format, used_args, opts),
+    do: collect_cc(:encoding, t, args, [p,?.|used_format], used_args, opts)
+
+  defp collect_cc(:pad_char, t, args, used_format, used_args, opts),
+    do: collect_cc(:encoding, t, args, used_format, used_args, opts)
+
+  ## encoding
+
+  defp collect_cc(:encoding, [?l|t], args, used_format, used_args, opts),
+    do: collect_cc(:done, t, args, [?l|used_format], used_args, %{opts | char_lists: false})
+
+  defp collect_cc(:encoding, [?t|t], args, used_format, used_args, opts),
+    do: collect_cc(:done, t, args, [?t|used_format], used_args, opts)
+
+  defp collect_cc(:encoding, t, args, used_format, used_args, opts),
+    do: collect_cc(:done, t, args, used_format, used_args, opts)
+
+  ## done
+
+  defp collect_cc(:done, [?W|t], [data, limit|args], _used_format, _used_args, opts),
+    do: collect_inspect(t, args, data, %{opts | limit: limit, width: :infinity})
+
+  defp collect_cc(:done, [?w|t], [data|args], _used_format, _used_args, opts),
+    do: collect_inspect(t, args, data, %{opts | width: :infinity})
+
+  defp collect_cc(:done, [?P|t], [data, limit|args], _used_format, _used_args, opts),
+    do: collect_inspect(t, args, data, %{opts | limit: limit})
+
+  defp collect_cc(:done, [?p|t], [data|args], _used_format, _used_args, opts),
+    do: collect_inspect(t, args, data, opts)
+
+  defp collect_cc(:done, [h|t], args, used_format, used_args, _opts) do
+    {args, used_args} = collect_cc(h, args, used_args)
+    {t, args, [h|used_format], used_args}
+  end
+
+  defp collect_cc(?x, [a,prefix|args], used), do: {args, [prefix, a|used]}
+  defp collect_cc(?X, [a,prefix|args], used), do: {args, [prefix, a|used]}
+  defp collect_cc(?s, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?e, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?f, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?g, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?b, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?B, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?+, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?#, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?c, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?i, [a|args], used), do: {args, [a|used]}
+  defp collect_cc(?~, args, used), do: {args, used}
+  defp collect_cc(?n, args, used), do: {args, used}
+
+  defp collect_inspect(t, args, data, opts) do
+    data =
+      data
+      |> Inspect.Algebra.to_doc(opts)
+      |> Inspect.Algebra.format(opts.width)
+    {t, args, 'st~', [data]}
+  end
+
+  defp collect_value(current, [?*|t], [arg|args], used_format, used_args, opts, next)
+      when is_integer(arg) do
+    collect_cc(next, t, args, [?*|used_format], [arg|used_args],
+               put_value(opts, current, arg))
+  end
+
+  defp collect_value(current, [c|t], args, used_format, used_args, opts, next)
+      when is_integer(c) and c >= ?0 and c <= ?9 do
+    {t, c} = collect_value([c|t], [])
+    collect_cc(next, t, args, c ++ used_format, used_args,
+               put_value(opts, current, c |> :lists.reverse |> List.to_integer))
+  end
+
+  defp collect_value(_current, t, args, used_format, used_args, opts, next),
+    do: collect_cc(next, t, args, used_format, used_args, opts)
+
+  defp collect_value([c|t], buffer)
+    when is_integer(c) and c >= ?0 and c <= ?9,
+    do: collect_value(t, [c|buffer])
+
+  defp collect_value(other, buffer),
+    do: {other, buffer}
+
+  defp put_value(opts, key, value) do
+    if Map.has_key?(opts, key) do
+      Map.put(opts, key, value)
+    else
+      opts
+    end
+  end
+
+  @doc """
+  Returns a timestamp that includes miliseconds.
+  """
+  def timestamp(utc_log?) do
+    {_, _, micro} = now = :os.timestamp()
+    {date, {hours, minutes, seconds}} =
+      case utc_log? do
+        true  -> :calendar.now_to_universal_time(now)
+        false -> :calendar.now_to_local_time(now)
+      end
+    {date, {hours, minutes, seconds, div(micro, 1000)}}
+  end
+
+  @doc """
+  Formats time to an iodata.
+  """
+  def format_time({hh, mi, ss, ms}) do
+    [pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., pad3(ms)]
+  end
+
+  @doc """
+  Formats date to an iodata.
+  """
+  def format_date({yy, mm, dd}) do
+    [Integer.to_string(yy), ?-, pad2(mm), ?-, pad2(dd)]
+  end
+
+  defp pad3(int) when int < 100 and int > 10, do: [?0, Integer.to_string(int)]
+  defp pad3(int) when int < 10, do: [?0, ?0, Integer.to_string(int)]
+  defp pad3(int), do: Integer.to_string(int)
+
+  defp pad2(int) when int < 10, do: [?0, Integer.to_string(int)]
+  defp pad2(int), do: Integer.to_string(int)
+end

lib/logger/lib/logger/watcher.ex

@@ -0,0 +1,91 @@
+defmodule Logger.Watcher do
+  @moduledoc false
+
+  require Logger
+  use GenServer
+  @name Logger.Watcher
+
+  @doc """
+  Starts the watcher supervisor.
+  """
+  def start_link(handlers) do
+    options  = [strategy: :one_for_one, name: @name]
+    case Supervisor.start_link([], options) do
+      {:ok, _} = ok ->
+        _ = for {mod, handler, args} <- handlers do
+          {:ok, _} = watch(mod, handler, args)
+        end
+        ok
+      {:error, _} = error ->
+        error
+    end
+  end
+
+  @doc """
+  Removes the given handler.
+  """
+  def unwatch(mod, handler) do
+    case Supervisor.terminate_child(@name, {mod, handler}) do
+      :ok -> Supervisor.delete_child(@name, {mod, handler})
+      res -> res
+    end
+  end
+
+  @doc """
+  Watches the given handler as part of the handler supervision tree.
+  """
+  def watch(mod, handler, args) do
+    import Supervisor.Spec
+    id = {mod, handler}
+    child = worker(__MODULE__, [mod, handler, args],
+      [id: id, function: :watcher, restart: :transient])
+    case Supervisor.start_child(@name, child) do
+      {:ok, _pid} = result ->
+        result
+      {:error, :already_present} ->
+        _ = Supervisor.delete_child(@name, id)
+        watch(mod, handler, args)
+      {:error, _reason} = error ->
+        error
+    end
+  end
+
+  @doc """
+  Starts a watcher server.
+
+  This is useful when there is a need to start a handler
+  outside of the handler supervision tree.
+  """
+  def watcher(mod, handler, args) do
+    GenServer.start_link(__MODULE__, {mod, handler, args})
+  end
+
+  ## Callbacks
+
+  def init({mod, handler, args}) do
+    case :gen_event.add_sup_handler(mod, handler, args) do
+      :ok               -> {:ok, {mod, handler}}
+      {:error, :ignore} -> :ignore
+      {:error, reason}  -> {:stop, reason}
+      {:EXIT, reason}   -> {:stop, reason}
+    end
+  end
+
+  def handle_info({:gen_event_EXIT, handler, reason}, {_, handler} = state)
+      when reason in [:normal, :shutdown] do
+    {:stop, reason, state}
+  end
+
+  def handle_info({:gen_event_EXIT, handler, reason}, {mod, handler} = state) do
+    Logger.error "GenEvent handler #{inspect handler} installed at #{inspect mod}\n" <>
+                 "** (exit) #{format_exit(reason)}"
+    {:stop, reason, state}
+  end
+
+  def handle_info(_msg, state) do
+    {:noreply, state}
+  end
+
+  defp format_exit({:EXIT, reason}), do: Exception.format_exit(reason)
+  defp format_exit(other), do: inspect(other)
+end

lib/logger/mix.exs

@@ -0,0 +1,24 @@
+defmodule Logger.Mixfile do
+  use Mix.Project
+
+  def project do
+    [app: :logger,
+     version: System.version,
+     build_per_environment: false]
+  end
+
+  def application do
+    [registered: [Logger, Logger.Supervisor, Logger.Watcher],
+     mod: {Logger, []},
+     env: [level: :debug,
+           utc_log: false,
+           truncate: 8096,
+           backends: [:console],
+           translators: [{Logger.Translator, :translate}],
+           sync_threshold: 20,
+           handle_otp_reports: true,
+           compile_time_purge_level: :debug,
+           discard_threshold_for_error_logger: 500,
+           console: []]]
+  end
+end

lib/logger/test/logger/backends/console_test.exs

@@ -0,0 +1,52 @@
+defmodule Logger.Backends.ConsoleTest do
+  use Logger.Case
+  require Logger
+
+  setup do
+    on_exit fn ->
+      :ok = Logger.configure_backend(:console, [format: nil, level: nil, metadata: []])
+    end
+  end
+
+  test "does not start when there is no user" do
+    user = Process.whereis(:user)
+
+    try do
+      Process.unregister(:user)
+      assert GenEvent.add_handler(Logger, Logger.Backends.Console, []) ==
+             {:error, :ignore}
+    after
+      Process.register(user, :user)
+    end
+  end
+
+  test "can configure format" do
+    Logger.configure_backend(:console, format: "$message [$level]")
+
+    assert capture_log(fn ->
+      Logger.debug("hello")
+    end) =~ "hello [debug]"
+  end
+
+  test "can configure metadata" do
+    Logger.configure_backend(:console, format: "$metadata$message", metadata: [:user_id])
+
+    assert capture_log(fn ->
+      Logger.debug("hello")
+    end) =~ "hello"
+
+    Logger.metadata(user_id: 13)
+
+    assert capture_log(fn ->
+      Logger.debug("user_id=13 hello")
+    end) =~ "hello"
+  end
+
+  test "can configure level" do
+    Logger.configure_backend(:console, level: :info)
+
+    assert capture_log(fn ->
+      Logger.debug("hello")
+    end) == ""
+  end
+end

lib/logger/test/logger/error_handler_test.exs

@@ -0,0 +1,59 @@
+defmodule Logger.ErrorHandlerTest do
+  use Logger.Case
+
+  test "survives after crashes" do
+    assert error_log(:info_msg, "~p~n", []) == ""
+    assert capture_log(fn ->
+      wait_for_handler(:error_logger, Logger.ErrorHandler)
+    end) =~ "[error] GenEvent handler Logger.ErrorHandler installed at :error_logger\n" <>
+            "** (exit) an exception was raised:"
+    assert error_log(:info_msg, "~p~n", [:hello]) =~ msg("[info] :hello\n")
+  end
+
+  test "formats error_logger info message" do
+    assert error_log(:info_msg, "hello", []) =~ msg("[info] hello")
+    assert error_log(:info_msg, "~p~n", [:hello]) =~ msg("[info] :hello\n")
+  end
+
+  test "formats error_logger info report" do
+    assert error_log(:info_report, "hello") =~ msg("[info] \"hello\"")
+    assert error_log(:info_report, :hello) =~ msg("[info] :hello\n")
+    assert error_log(:info_report, :special, :hello) == ""
+  end
+
+  test "formats error_logger error message" do
+    assert error_log(:error_msg, "hello", []) =~ msg("[error] hello")
+    assert error_log(:error_msg, "~p~n", [:hello]) =~ msg("[error] :hello\n")
+  end
+
+  test "formats error_logger error report" do
+    assert error_log(:error_report, "hello") =~ msg("[error] \"hello\"")
+    assert error_log(:error_report, :hello) =~ msg("[error] :hello\n")
+    assert error_log(:error_report, :special, :hello) == ""
+  end
+
+  test "formats error_logger warning message" do
+    # Warnings by default are logged as errors by Erlang
+    assert error_log(:warning_msg, "hello", []) =~ msg("[error] hello")
+    assert error_log(:warning_msg, "~p~n", [:hello]) =~ msg("[error] :hello\n")
+  end
+
+  test "formats error_logger warning report" do
+    # Warnings by default are logged as errors by Erlang
+    assert error_log(:warning_report, "hello") =~ msg("[error] \"hello\"")
+    assert error_log(:warning_report, :hello) =~ msg("[error] :hello\n")
+    assert error_log(:warning_report, :special, :hello) == ""
+  end
+
+  defp error_log(fun, format) do
+    do_error_log(fun, [format])
+  end
+
+  defp error_log(fun, format, args) do
+    do_error_log(fun, [format, args])
+  end
+
+  defp do_error_log(fun, args) do
+    capture_log(fn -> apply(:error_logger, fun, args) end)
+  end
+end

lib/logger/test/logger/formatter_test.exs

@@ -0,0 +1,54 @@
+defmodule Logger.FormatterTest do
+  use Logger.Case, async: true
+  doctest Logger.Formatter
+
+  import Logger.Formatter
+
+  defmodule CompileMod do
+    def format(_level, _msg, _ts, _md) do
+      true
+    end
+  end
+
+  test "compile/1 with nil" do
+    assert compile(nil) ==
+           [:time, " ", :metadata, "[", :level, "] ", :message, "\n"]
+  end
+
+  test "compile/1 with str" do
+    assert compile("$level $time $date $metadata $message $node") ==
+           Enum.intersperse([:level, :time, :date, :metadata, :message, :node], " ")
+
+    assert_raise ArgumentError,"$bad is an invalid format pattern.", fn ->
+      compile("$bad $good")
+    end
+  end
+
+  test "compile/1 with {mod, fun}" do
+    assert compile({CompileMod, :format}) == {CompileMod, :format}
+  end
+
+  test "format with {mod, fun}" do
+    assert format({CompileMod, :format}, nil, nil, nil,nil) == true
+  end
+
+  test "format with format string" do
+    compiled = compile("[$level] $message")
+    assert format(compiled, :error, "hello", nil, []) ==
+           ["[", "error", "] ", "hello"]
+
+    compiled = compile("$node")
+    assert format(compiled, :error, nil, nil, []) == [Atom.to_string(node())]
+
+    compiled = compile("$metadata")
+    assert IO.iodata_to_binary(format(compiled, :error, nil, nil, [meta: :data])) ==
+           "meta=data "
+    assert IO.iodata_to_binary(format(compiled, :error, nil, nil, [])) ==
+           ""
+
+    timestamp = {{2014, 12, 30}, {12, 6, 30, 100}}
+    compiled = compile("$date $time")
+    assert IO.iodata_to_binary(format(compiled, :error, nil, timestamp, [])) ==
+           "2014-12-30 12:06:30.100"
+  end
+end

lib/logger/test/logger/translator_test.exs

@@ -0,0 +1,102 @@
+defmodule Logger.TranslatorTest do
+  use Logger.Case
+
+  defmodule MyGenServer do
+    use GenServer
+
+    def handle_call(:error, _, _) do
+      raise "oops"
+    end
+  end
+
+  defmodule MyGenEvent do
+    use GenEvent
+
+    def handle_call(:error, _) do
+      raise "oops"
+    end
+  end
+
+  test "translates GenServer crashes" do
+    {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+    assert capture_log(:info, fn ->
+      catch_exit(GenServer.call(pid, :error))
+    end) =~ """
+    [error] GenServer #{inspect pid} terminating
+    ** (exit) an exception was raised:
+        ** (RuntimeError) oops
+    """
+  end
+
+  test "translates GenServer crashes on debug" do
+    {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+    assert capture_log(:debug, fn ->
+      catch_exit(GenServer.call(pid, :error))
+    end) =~ """
+    [error] GenServer #{inspect pid} terminating
+    Last message: :error
+    State: :ok
+    ** (exit) an exception was raised:
+        ** (RuntimeError) oops
+    """
+  end
+
+  test "translates GenEvent crashes" do
+    {:ok, pid} = GenEvent.start()
+    :ok = GenEvent.add_handler(pid, MyGenEvent, :ok)
+
+    assert capture_log(:info, fn ->
+      GenEvent.call(pid, MyGenEvent, :error)
+    end) =~ """
+    [error] GenEvent handler Logger.TranslatorTest.MyGenEvent installed in #{inspect pid} terminating
+    ** (exit) an exception was raised:
+        ** (RuntimeError) oops
+    """
+  end
+
+  test "translates GenEvent crashes on debug" do
+    {:ok, pid} = GenEvent.start()
+    :ok = GenEvent.add_handler(pid, MyGenEvent, :ok)
+
+    assert capture_log(:debug, fn ->
+      GenEvent.call(pid, MyGenEvent, :error)
+    end) =~ """
+    [error] GenEvent handler Logger.TranslatorTest.MyGenEvent installed in #{inspect pid} terminating
+    Last message: :error
+    State: :ok
+    ** (exit) an exception was raised:
+        ** (RuntimeError) oops
+    """
+  end
+
+  test "translates Task crashes" do
+    {:ok, pid} = Task.start_link(__MODULE__, :task, [self()])
+
+    assert capture_log(fn ->
+      ref = Process.monitor(pid)
+      send(pid, :go)
+      receive do: ({:DOWN, ^ref, _, _, _} -> :ok)
+    end) =~ """
+    [error] Task #{inspect pid} started from #{inspect self} terminating
+    Function: &Logger.TranslatorTest.task/1
+        Args: [#{inspect self}]
+    ** (exit) an exception was raised:
+        ** (RuntimeError) oops
+    """
+  end
+
+  test "translates application stop" do
+    :ok = Application.start(:eex)
+
+    assert capture_log(fn ->
+      Application.stop(:eex)
+    end) =~ msg("[info] Application eex exited with reason :stopped")
+  end
+
+  def task(parent) do
+    Process.unlink(parent)
+    receive do: (:go -> raise "oops")
+  end
+end

lib/logger/test/logger/utils_test.exs

@@ -0,0 +1,96 @@
+defmodule Logger.UtilsTest do
+  use Logger.Case, async: true
+
+  import Logger.Utils
+
+  import Kernel, except: [inspect: 2]
+  defp inspect(format, args), do: Logger.Utils.inspect(format, args, 10)
+
+  test "truncate/2" do
+    # ASCII binaries
+    assert truncate("foo", 4) == "foo"
+    assert truncate("foo", 3) == "foo"
+    assert truncate("foo", 2) == ["fo", " (truncated)"]
+
+    # UTF-8 binaries
+    assert truncate("olá", 2) == ["ol", " (truncated)"]
+    assert truncate("olá", 3) == ["ol", " (truncated)"]
+    assert truncate("olá", 4) == "olá"
+    assert truncate("ááááá:", 10)  == ["ááááá", " (truncated)"]
+    assert truncate("áááááá:", 10) == ["ááááá", " (truncated)"]
+
+    # Charlists
+    assert truncate('olá', 2) == ['olá', " (truncated)"]
+    assert truncate('olá', 3) == ['olá', " (truncated)"]
+    assert truncate('olá', 4) == 'olá'
+
+    # Chardata
+    assert truncate('ol' ++ "á", 2) == ['ol' ++ "", " (truncated)"]
+    assert truncate('ol' ++ "á", 3) == ['ol' ++ "", " (truncated)"]
+    assert truncate('ol' ++ "á", 4) == 'ol' ++ "á"
+  end
+
+  test "inspect/2 formats" do
+    assert inspect('~p', [1])  == {'~ts', [["1"]]}
+    assert inspect("~p", [1])  == {'~ts', [["1"]]}
+    assert inspect(:"~p", [1]) == {'~ts', [["1"]]}
+  end
+
+  test "inspect/2 sigils" do
+    assert inspect('~10.10tp', [1]) == {'~ts', [["1"]]}
+    assert inspect('~-10.10tp', [1]) == {'~ts', [["1"]]}
+
+    assert inspect('~10.10lp', [1]) == {'~ts', [["1"]]}
+    assert inspect('~10.10x~p~n', [1, 2, 3]) == {'~10.10x~ts~n', [1, 2, ["3"]]}
+  end
+
+  test "inspect/2 with modifier t has no effect (as it is the default)" do
+    assert inspect('~tp', [1]) == {'~ts', [["1"]]}
+    assert inspect('~tw', [1]) == {'~ts', [["1"]]}
+  end
+
+  test "inspect/2 with modifier l always prints lists" do
+    assert inspect('~lp', ['abc']) ==
+           {'~ts', [["[", "97", ",", " ", "98", ",", " ", "99", "]"]]}
+    assert inspect('~lw', ['abc']) ==
+           {'~ts', [["[", "97", ",", " ", "98", ",", " ", "99", "]"]]}
+  end
+
+  test "inspect/2 with modifier for width" do
+    assert inspect('~5lp', ['abc']) ==
+           {'~ts', [["[", "97", ",", "\n ", "98", ",", "\n ", "99", "]"]]}
+
+    assert inspect('~5lw', ['abc']) ==
+           {'~ts', [["[", "97", ",", " ", "98", ",", " ", "99", "]"]]}
+  end
+
+  test "inspect/2 with modifier for limit" do
+    assert inspect('~5lP', ['abc', 2]) ==
+           {'~ts', [["[", "97", ",", "\n ", "98", ",", "\n ", "...", "]"]]}
+
+    assert inspect('~5lW', ['abc', 2]) ==
+           {'~ts', [["[", "97", ",", " ", "98", ",", " ", "...", "]"]]}
+  end
+
+  test "inspect/2 truncates binaries" do
+    assert inspect('~ts', ["abcdeabcdeabcdeabcde"]) ==
+           {'~ts', ["abcdeabcde"]}
+
+    assert inspect('~ts~ts~ts', ["abcdeabcde", "abcde", "abcde"]) ==
+           {'~ts~ts~ts', ["abcdeabcde", "", ""]}
+  end
+
+  test "timestamp" do
+    assert {{_, _, _}, {_, _, _, _}} = timestamp(true)
+  end
+
+  test "format_date" do
+    date = {2015, 1, 30}
+    assert format_date(date) == ["2015", ?-, [?0, "1"], ?-, "30"]
+  end
+
+  test "format_time" do
+    time = {12, 30, 10, 1}
+    assert format_time(time) == ["12", ?:, "30", ?:, "10", ?., [?0, ?0, "1"]]
+  end
+end

lib/logger/test/logger_test.exs

@@ -0,0 +1,175 @@
+defmodule LoggerTest do
+  use Logger.Case
+  require Logger
+
+  test "add_translator/1 and remove_translator/1" do
+    defmodule CustomTranslator do
+      def t(:debug, :info, :format, {'hello: ~p', [:ok]}) do
+        :skip
+      end
+
+      def t(:debug, :info, :format, {'world: ~p', [:ok]}) do
+        {:ok, "rewritten"}
+      end
+
+      def t(_, _, _, _) do
+        :none
+      end
+    end
+
+    assert Logger.add_translator({CustomTranslator, :t})
+
+    assert capture_log(fn ->
+      :error_logger.info_msg('hello: ~p', [:ok])
+    end) == ""
+
+    assert capture_log(fn ->
+      :error_logger.info_msg('world: ~p', [:ok])
+    end) =~ "\[info\] rewritten"
+  after
+    assert Logger.remove_translator({CustomTranslator, :t})
+  end
+
+  test "add_backend/1 and remove_backend/1" do
+    assert :ok = Logger.remove_backend(:console)
+    assert Logger.remove_backend(:console) ==
+           {:error, :not_found}
+
+    assert capture_log(fn ->
+      assert Logger.debug("hello", []) == :ok
+    end) == ""
+
+    assert {:ok, pid} = Logger.add_backend(:console)
+    assert Logger.add_backend(:console) ==
+           {:error, {:already_started, pid}}
+  end
+
+  test "level/0" do
+    assert Logger.level == :debug
+  end
+
+  test "compare_levels/2" do
+    assert Logger.compare_levels(:debug, :debug) == :eq
+    assert Logger.compare_levels(:debug, :info)  == :lt
+    assert Logger.compare_levels(:debug, :warn)  == :lt
+    assert Logger.compare_levels(:debug, :error) == :lt
+
+    assert Logger.compare_levels(:info, :debug) == :gt
+    assert Logger.compare_levels(:info, :info)  == :eq
+    assert Logger.compare_levels(:info, :warn)  == :lt
+    assert Logger.compare_levels(:info, :error) == :lt
+
+    assert Logger.compare_levels(:warn, :debug) == :gt
+    assert Logger.compare_levels(:warn, :info)  == :gt
+    assert Logger.compare_levels(:warn, :warn)  == :eq
+    assert Logger.compare_levels(:warn, :error) == :lt
+
+    assert Logger.compare_levels(:error, :debug) == :gt
+    assert Logger.compare_levels(:error, :info)  == :gt
+    assert Logger.compare_levels(:error, :warn)  == :gt
+    assert Logger.compare_levels(:error, :error) == :eq
+  end
+
+  test "debug/2" do
+    assert capture_log(fn ->
+      assert Logger.debug("hello", []) == :ok
+    end) =~ msg("[debug] hello")
+
+    assert capture_log(:info, fn ->
+      assert Logger.debug("hello", []) == :ok
+    end) == ""
+  end
+
+  test "info/2" do
+    assert capture_log(fn ->
+      assert Logger.info("hello", []) == :ok
+    end) =~ msg("[info] hello")
+
+    assert capture_log(:warn, fn ->
+      assert Logger.info("hello", []) == :ok
+    end) == ""
+  end
+
+  test "warn/2" do
+    assert capture_log(fn ->
+      assert Logger.warn("hello", []) == :ok
+    end) =~ msg("[warn] hello")
+
+    assert capture_log(:error, fn ->
+      assert Logger.warn("hello", []) == :ok
+    end) == ""
+  end
+
+  test "error/2" do
+    assert capture_log(fn ->
+      assert Logger.error("hello", []) == :ok
+    end) =~ msg("[error] hello")
+  end
+
+  test "remove unused calls at compile time" do
+    Logger.configure(compile_time_purge_level: :info)
+
+    defmodule Sample do
+      def debug do
+        Logger.debug "hello"
+      end
+
+      def info do
+        Logger.info "hello"
+      end
+    end
+
+    assert capture_log(fn ->
+      assert Sample.debug == :ok
+    end) == ""
+
+    assert capture_log(fn ->
+      assert Sample.info == :ok
+    end) =~ msg("[info] hello")
+  after
+    Logger.configure(compile_time_purge_level: :debug)
+  end
+
+  test "log/2 truncates messages" do
+    Logger.configure(truncate: 4)
+    assert capture_log(fn ->
+      Logger.log(:debug, "hello")
+    end) =~ "hell (truncated)"
+  after
+    Logger.configure(truncate: 8096)
+  end
+
+  test "log/2 fails when the application is off" do
+    logger = Process.whereis(Logger)
+    Process.unregister(Logger)
+
+    try do
+      assert_raise RuntimeError,
+                   "Cannot log messages, the :logger application is not running", fn ->
+        Logger.log(:debug, "hello")
+      end
+    after
+      Process.register(logger, Logger)
+    end
+  end
+
+  test "Logger.Config survives Logger exit" do
+    Process.whereis(Logger)
+      |> Process.exit(:kill)
+    wait_for_logger()
+    wait_for_handler(Logger, Logger.Config)
+  end
+
+  test "Logger.Config can restart the application" do
+    Application.put_env(:logger, :backends, [])
+    Logger.Config.restart()
+
+    assert capture_log(fn ->
+      assert Logger.debug("hello", []) == :ok
+    end) == ""
+
+    assert {:ok, pid} = Logger.add_backend(:console)
+    assert Logger.add_backend(:console) ==
+           {:error, {:already_started, pid}}
+  end
+end

lib/logger/test/test_helper.exs

@@ -0,0 +1,47 @@
+ExUnit.start seed: 362385, trace: true
+
+defmodule Logger.Case do
+  use ExUnit.CaseTemplate
+  import ExUnit.CaptureIO
+
+  using _ do
+    quote do
+      import Logger.Case
+    end
+  end
+
+  def msg(msg) do
+    ~r/^\d\d\:\d\d\:\d\d\.\d\d\d #{Regex.escape(msg)}$/
+  end
+
+  def wait_for_handler(manager, handler) do
+    unless handler in GenEvent.which_handlers(manager) do
+      :timer.sleep(10)
+      wait_for_handler(manager, handler)
+    end
+  end
+
+  def wait_for_logger() do
+    try do
+      GenEvent.which_handlers(Logger)
+    else
+      _ ->
+        :ok
+    catch
+      :exit, _ ->
+        :timer.sleep(10)
+        wait_for_logger()
+    end
+  end
+
+  def capture_log(level \\ :debug, fun) do
+    Logger.configure(level: level)
+    capture_io(:user, fn ->
+      fun.()
+      GenEvent.which_handlers(:error_logger)
+      GenEvent.which_handlers(Logger)
+    end)
+  after
+    Logger.configure(level: :debug)
+  end
+end

lib/mix/lib/mix/tasks/new.ex

@@ -98,11 +98,11 @@ defmodule Mix.Tasks.New do
   end
 
   defp otp_app(_mod, false) do
-    "    [applications: []]"
+    "    [applications: [:logger]]"
   end
 
   defp otp_app(mod, true) do
-    "    [applications: [],\n     mod: {#{mod}, []}]"
+    "    [applications: [:logger],\n     mod: {#{mod}, []}]"
   end
 
   defp do_generate_umbrella(app, path, _opts) do
@@ -275,14 +275,14 @@ defmodule Mix.Tasks.New do
   # This configuration is loaded before any dependency and is restricted
   # to this project. If another project depends on this project, this
   # file won't be loaded nor affect the parent project. For this reason,
-  # if you want to provide default values for your application, it should
-  # be done in your mix.exs file.
+  # if you want to provide default values for your application for third-
+  # party users, it should be done in your mix.exs file.
 
   # Sample configuration:
   #
-  #     config :my_dep,
-  #       key: :value,
-  #       limit: 42
+  #     config :logger,
+  #       level: :info,
+  #       format: "$time $metadata[$level] $message\n"
 
   # It is also possible to import configuration files, relative to this
   # directory. For example, you can emulate configuration per environment