Deprecate levelpad of Logger.Formatter (#11633)

Author: nallwhy

lib/ex_unit/test/ex_unit/capture_log_test.exs

@@ -72,7 +72,7 @@ defmodule ExUnit.CaptureLogTest do
       end)
 
     assert logged
-    assert logged =~ "[info]  one\n"
+    assert logged =~ "[info] one\n"
     assert logged =~ "[warning] two\n"
     assert logged =~ "[debug] three\n"
     assert logged =~ "[error] one\n"

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

@@ -9,7 +9,7 @@ defmodule Logger.Backends.Console do
       `:level` configuration for the `:logger` application first.
 
     * `:format` - the format message used to print logs.
-      Defaults to: `"\n$time $metadata[$level] $levelpad$message\n"`.
+      Defaults to: `"\n$time $metadata[$level] $message\n"`.
       It may also be a `{module, function}` tuple that is invoked
       with the log level, the message, the current timestamp and
       the metadata.
@@ -48,7 +48,7 @@ defmodule Logger.Backends.Console do
   `config/config.exs` file:
 
       config :logger, :console,
-        format: "\n$time $metadata[$level] $levelpad$message\n",
+        format: "\n$time $metadata[$level] $message\n",
         metadata: [:user_id]
 
   ## Custom formatting

lib/logger/lib/logger/formatter.ex

@@ -21,8 +21,6 @@ defmodule Logger.Formatter do
     * `$level`    - the log level
     * `$node`     - the node that prints the message
     * `$metadata` - user controlled data presented in `"key=val key2=val2 "` format
-    * `$levelpad` - sets to a single space if level is 4 characters long,
-      otherwise set to the empty space. Used to align the message after level.
 
   Backends typically allow developers to supply such control
   strings via configuration files. This module provides `compile/1`,
@@ -43,7 +41,7 @@ defmodule Logger.Formatter do
   @type time :: {{1970..10000, 1..12, 1..31}, {0..23, 0..59, 0..59, 0..999}}
   @type pattern :: :date | :level | :levelpad | :message | :metadata | :node | :time
   @valid_patterns [:time, :date, :message, :level, :node, :metadata, :levelpad]
-  @default_pattern "\n$time $metadata[$level] $levelpad$message\n"
+  @default_pattern "\n$time $metadata[$level] $message\n"
   @replacement "�"
 
   @doc """
@@ -99,6 +97,11 @@ defmodule Logger.Formatter do
     end
   end
 
+  defp compile_code(:levelpad) do
+    IO.warn("$levelpad in Logger message format is deprecated, please remove it")
+    :levelpad
+  end
+
   defp compile_code(key) when key in @valid_patterns, do: key
 
   defp compile_code(key) when is_atom(key) do
@@ -163,7 +166,6 @@ defmodule Logger.Formatter do
   defp output(:levelpad, level, _, _, _), do: levelpad(level)
   defp output(other, _, _, _, _), do: other
 
-  # TODO: Deprecate me on Elixir v1.13+ or later
   defp levelpad(:info), do: " "
   defp levelpad(:warn), do: " "
   defp levelpad(_), do: ""

lib/logger/test/logger/formatter_test.exs

@@ -20,7 +20,7 @@ defmodule Logger.FormatterTest do
 
   test "compile/1 with nil" do
     assert compile(nil) ==
-             ["\n", :time, " ", :metadata, "[", :level, "] ", :levelpad, :message, "\n"]
+             ["\n", :time, " ", :metadata, "[", :level, "] ", :message, "\n"]
   end
 
   test "compile/1 with str" do
@@ -90,12 +90,6 @@ defmodule Logger.FormatterTest do
              [["foo", 61, "bar", 32], " ", "hello"]
   end
 
-  test "padding takes account of length of level" do
-    compiled = compile("[$level] $levelpad $message")
-    assert format(compiled, :error, "hello", nil, []) == ["[", "error", "] ", "", " ", "hello"]
-    assert format(compiled, :info, "hello", nil, []) == ["[", "info", "] ", " ", " ", "hello"]
-  end
-
   test "format_date/1" do
     date = {2015, 1, 30}
     assert format_date(date) == ["2015", ?-, [?0, "1"], ?-, "30"]

lib/logger/test/logger/handler_test.exs

@@ -51,15 +51,15 @@ defmodule Logger.HandlerTest do
 
     assert capture_log(fn ->
              :logger.info('world: ~p', [:ok])
-           end) =~ "[info]  rewritten"
+           end) =~ "[info] rewritten"
 
     assert capture_log(fn ->
              :logger.info(%{hello: :ok})
            end) == ""
 
     assert capture_log(fn ->
              :logger.info(%{world: :ok})
-           end) =~ "[info]  rewritten"
+           end) =~ "[info] rewritten"
   after
     assert Logger.remove_translator({CustomTranslator, :t})
   end
@@ -68,7 +68,7 @@ defmodule Logger.HandlerTest do
     assert Logger.add_translator({CustomTranslator, :t})
 
     message = capture_log(fn -> :logger.info(%{error: "oops"}) end)
-    assert message =~ "[info]  Failure while translating Erlang's logger event\n"
+    assert message =~ "[info] Failure while translating Erlang's logger event\n"
     assert message =~ "** (RuntimeError) oops\n"
   after
     assert Logger.remove_translator({CustomTranslator, :t})
@@ -94,7 +94,7 @@ defmodule Logger.HandlerTest do
     assert capture_log(fn ->
              callback = fn %{hello: :world} -> {"~p~n", [:formatted]} end
              :logger.info(%{hello: :world}, %{report_cb: callback})
-           end) =~ "[info]  :formatted"
+           end) =~ "[info] :formatted"
   end
 
   test "uses Erlang log levels" do
@@ -104,7 +104,7 @@ defmodule Logger.HandlerTest do
     assert capture_log(fn -> :logger.error('ok') end) =~ "[error] ok"
     assert capture_log(fn -> :logger.warning('ok') end) =~ "[warning] ok"
     assert capture_log(fn -> :logger.notice('ok') end) =~ "[notice] ok"
-    assert capture_log(fn -> :logger.info('ok') end) =~ "[info]  ok"
+    assert capture_log(fn -> :logger.info('ok') end) =~ "[info] ok"
     assert capture_log(fn -> :logger.debug('ok') end) =~ "[debug] ok"
   end
 

lib/logger/test/logger/translator_test.exs

@@ -713,7 +713,7 @@ defmodule Logger.TranslatorTest do
              Process.exit(pid, :normal)
              receive do: ({:DOWN, ^ref, _, _, _} -> :ok)
            end) =~ ~r"""
-           \[info\]  Child Task of Supervisor #PID<\d+\.\d+\.\d+> \(Supervisor\.Default\) started
+           \[info\] Child Task of Supervisor #PID<\d+\.\d+\.\d+> \(Supervisor\.Default\) started
            Pid: #PID<\d+\.\d+\.\d+>
            Start Call: Task.start_link\(Logger.TranslatorTest, :sleep, \[#PID<\d+\.\d+\.\d+>\]\)
            """
@@ -728,7 +728,7 @@ defmodule Logger.TranslatorTest do
              Process.exit(pid, :normal)
              receive do: ({:DOWN, ^ref, _, _, _} -> :ok)
            end) =~ ~r"""
-           \[info\]  Child Task of Supervisor Logger.TranslatorTest started
+           \[info\] Child Task of Supervisor Logger.TranslatorTest started
            """
 
     {:ok, pid} = Supervisor.start_link([], strategy: :one_for_one, name: {:global, __MODULE__})
@@ -739,7 +739,7 @@ defmodule Logger.TranslatorTest do
              Process.exit(pid, :normal)
              receive do: ({:DOWN, ^ref, _, _, _} -> :ok)
            end) =~ ~r"""
-           \[info\]  Child Task of Supervisor Logger.TranslatorTest started
+           \[info\] Child Task of Supervisor Logger.TranslatorTest started
            """
 
     {:ok, pid} =
@@ -751,7 +751,7 @@ defmodule Logger.TranslatorTest do
              Process.exit(pid, :normal)
              receive do: ({:DOWN, ^ref, _, _, _} -> :ok)
            end) =~ ~r"""
-           \[info\]  Child Task of Supervisor Logger.TranslatorTest started
+           \[info\] Child Task of Supervisor Logger.TranslatorTest started
            """
   end
 
@@ -960,7 +960,7 @@ defmodule Logger.TranslatorTest do
              receive do: ({:EXIT, ^pid, _} -> :ok)
              Process.flag(:trap_exit, trap)
            end) =~ ~r"""
-           \[info\]  Child of Supervisor #PID<\d+\.\d+\.\d+> \(Logger\.TranslatorTest\.MyBridge\) started
+           \[info\] Child of Supervisor #PID<\d+\.\d+\.\d+> \(Logger\.TranslatorTest\.MyBridge\) started
            Pid: #PID<\d+\.\d+\.\d+>
            Start Call: Logger.TranslatorTest.MyBridge.init\(:normal\)
            """

lib/logger/test/logger_test.exs

@@ -270,15 +270,15 @@ defmodule LoggerTest do
 
     assert capture_log(fn ->
              assert Logger.bare_log(:info, "ok", application: nil, module: LoggerTest) == :ok
-           end) =~ msg("module=LoggerTest [info]  ok")
+           end) =~ msg("module=LoggerTest [info] ok")
   end
 
   test "metadata compile-time merge" do
     assert Logger.metadata(module: Sample) == :ok
 
     assert capture_log(fn ->
              assert Logger.log(:info, "ok", application: nil, module: CustomTest) == :ok
-           end) =~ msg("module=CustomTest [info]  ok")
+           end) =~ msg("module=CustomTest [info] ok")
   end
 
   test "metadata merge when the argument function returns metadata" do
@@ -288,7 +288,7 @@ defmodule LoggerTest do
 
     assert capture_log(fn ->
              assert Logger.bare_log(:info, fun, application: nil, module: LoggerTest) == :ok
-           end) =~ msg("module=Function [info]  ok")
+           end) =~ msg("module=Function [info] ok")
   end
 
   describe "log with function" do
@@ -297,15 +297,15 @@ defmodule LoggerTest do
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, fun, application: nil, module: FunctionTest) == :ok
-             end) =~ msg("module=FunctionTest [info]  ok:example")
+             end) =~ msg("module=FunctionTest [info] ok:example")
     end
 
     test "supports binaries" do
       fun = fn -> "ok:example" end
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, fun, application: nil, module: FunctionTest) == :ok
-             end) =~ msg("module=FunctionTest [info]  ok:example")
+             end) =~ msg("module=FunctionTest [info] ok:example")
     end
   end
 
@@ -314,41 +314,41 @@ defmodule LoggerTest do
       assert capture_log(fn ->
                assert Logger.bare_log(:info, %{foo: 10}, application: nil, module: FunctionTest) ==
                         :ok
-             end) =~ msg("module=FunctionTest [info]  [foo: 10]")
+             end) =~ msg("module=FunctionTest [info] [foo: 10]")
     end
 
     test "supports keyword" do
       assert capture_log(fn ->
                assert Logger.bare_log(:info, foo: 10) == :ok
-             end) =~ msg("[info]  [foo: 10]")
+             end) =~ msg("[info] [foo: 10]")
     end
 
     test "supports custom report_cb" do
       report_cb = fn %{foo: foo} -> {"Foo is ~B", [foo]} end
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, %{foo: 10}, report_cb: report_cb) == :ok
-             end) =~ msg("[info]  Foo is 10")
+             end) =~ msg("[info] Foo is 10")
 
       report_cb = fn %{foo: foo}, _opts -> "Foo is #{foo}" end
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, %{foo: 20}, report_cb: report_cb) == :ok
-             end) =~ msg("[info]  Foo is 20")
+             end) =~ msg("[info] Foo is 20")
     end
 
     test "support function that return report" do
       assert capture_log(fn ->
                assert Logger.bare_log(:info, fn -> %{foo: 10} end) == :ok
-             end) =~ msg("[info]  [foo: 10]")
+             end) =~ msg("[info] [foo: 10]")
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, fn -> {%{foo: 10}, []} end) == :ok
-             end) =~ msg("[info]  [foo: 10]")
+             end) =~ msg("[info] [foo: 10]")
 
       assert capture_log(fn ->
                assert Logger.bare_log(:info, fn -> {[foo: 10], []} end) == :ok
-             end) =~ msg("[info]  [foo: 10]")
+             end) =~ msg("[info] [foo: 10]")
     end
   end
 
@@ -437,7 +437,7 @@ defmodule LoggerTest do
     test "info/2" do
       assert capture_log(fn ->
                assert Logger.info("hello", []) == :ok
-             end) =~ msg_with_meta("[info]  hello")
+             end) =~ msg_with_meta("[info] hello")
 
       assert capture_log(:notice, fn ->
                assert Logger.info("hello", []) == :ok
@@ -598,7 +598,7 @@ defmodule LoggerTest do
 
     assert capture_log(fn ->
              assert SampleNoApp.info() == :ok
-           end) =~ msg("module=LoggerTest.SampleNoApp [info]  hello")
+           end) =~ msg("module=LoggerTest.SampleNoApp [info] hello")
 
     Logger.configure(compile_time_application: :sample_app)
 
@@ -610,7 +610,7 @@ defmodule LoggerTest do
 
     assert capture_log(fn ->
              assert SampleApp.info() == :ok
-           end) =~ msg("application=sample_app module=LoggerTest.SampleApp [info]  hello")
+           end) =~ msg("application=sample_app module=LoggerTest.SampleApp [info] hello")
   after
     Logger.configure(compile_time_application: nil)
   end
@@ -721,8 +721,8 @@ defmodule LoggerTest do
         Logger.flush()
       end)
 
-    assert log =~ ~r"\[warn\]  Attempted to log \d+ messages, which is above :discard_threshold"
-    assert log =~ ~r"\[warn\]  Attempted to log \d+ messages, which is below :discard_threshold"
+    assert log =~ ~r"\[warn\] Attempted to log \d+ messages, which is above :discard_threshold"
+    assert log =~ ~r"\[warn\] Attempted to log \d+ messages, which is below :discard_threshold"
   after
     :sys.resume(Logger)
     assert :ok = Logger.configure(discard_threshold: 500)