diff --git a/config/config.exs b/config/config.exs index b8525bd..499ba35 100644 --- a/config/config.exs +++ b/config/config.exs @@ -1,6 +1,6 @@ # This file is responsible for configuring your application # and its dependencies with the aid of the Mix.Config module. -use Mix.Config +import Config # This configuration is loaded before any dependency and is restricted # to this project. If another project depends on this project, this diff --git a/config/dev.exs b/config/dev.exs index 897da70..f9f3121 100644 --- a/config/dev.exs +++ b/config/dev.exs @@ -1,4 +1,4 @@ -use Mix.Config +import Config config :logger, backends: [{LoggerFileBackend, :dev_backend}], diff --git a/config/test.exs b/config/test.exs index 6bd53a5..84355f5 100644 --- a/config/test.exs +++ b/config/test.exs @@ -1,4 +1,4 @@ -use Mix.Config +import Config config :logger, backends: [] diff --git a/lib/logger_file_backend.ex b/lib/logger_file_backend.ex index 7493487..d2d3b5b 100644 --- a/lib/logger_file_backend.ex +++ b/lib/logger_file_backend.ex @@ -8,9 +8,10 @@ defmodule LoggerFileBackend do @type path :: String.t() @type file :: :file.io_device() @type inode :: integer - @type format :: String.t() + @type format :: {atom(), atom()} | [Logger.Formatter.pattern() | binary()] @type level :: Logger.level() @type metadata :: [atom] + @type formatter :: module() require Record Record.defrecordp(:file_info, Record.extract(:file_info, from_lib: "kernel/include/file.hrl")) @@ -114,7 +115,7 @@ defmodule LoggerFileBackend do defp rename_file(path, keep) do File.rm("#{path}.#{keep}") - Enum.each((keep - 1)..1, fn x -> File.rename("#{path}.#{x}", "#{path}.#{x + 1}") end) + Enum.each((keep - 1)..1//-1, fn x -> File.rename("#{path}.#{x}", "#{path}.#{x + 1}") end) case File.rename(path, "#{path}.1") do :ok -> false @@ -148,10 +149,30 @@ defmodule LoggerFileBackend do end end - defp format_event(level, msg, ts, md, %{format: format, metadata: keys}) do + defp format_event(level, msg, ts, md, %{ + format: format, + formatter: Logger.Formatter, + metadata: keys + }) do Logger.Formatter.format(format, level, msg, ts, take_metadata(md, keys)) end + # md should be a map + defp format_event(level, msg, ts, md, opts) when is_list(md) do + format_event(level, msg, ts, Enum.into(md, %{}), opts) + end + + defp format_event(level, msg, ts, md, %{ + format: _format, + formatter: {formatter_module, formatter_opts}, + metadata: _metadata + }) do + apply(formatter_module, :format, [ + %{level: level, msg: {:string, msg}, meta: Map.put(md, :time, ts)}, + formatter_opts + ]) + end + @doc false @spec metadata_matches?(Keyword.t(), nil | Keyword.t()) :: true | false def metadata_matches?(_md, nil), do: true @@ -208,6 +229,7 @@ defmodule LoggerFileBackend do io_device: nil, inode: nil, format: nil, + formatter: nil, level: nil, metadata: nil, metadata_filter: nil, @@ -225,8 +247,9 @@ defmodule LoggerFileBackend do level = Keyword.get(opts, :level) metadata = Keyword.get(opts, :metadata, []) - format_opts = Keyword.get(opts, :format, @default_format) - format = Logger.Formatter.compile(format_opts) + format_opts = Keyword.get(opts, :format) + format = Logger.Formatter.compile(format_opts || @default_format) + formatter = Keyword.get(opts, :formatter) path = Keyword.get(opts, :path) metadata_filter = Keyword.get(opts, :metadata_filter) metadata_reject = Keyword.get(opts, :metadata_reject) @@ -237,6 +260,7 @@ defmodule LoggerFileBackend do | name: name, path: path, format: format, + formatter: formatter || Logger.Formatter, level: level, metadata: metadata, metadata_filter: metadata_filter, diff --git a/mix.exs b/mix.exs index f011193..9e7a80a 100644 --- a/mix.exs +++ b/mix.exs @@ -42,6 +42,7 @@ defmodule LoggerFileBackend.Mixfile do defp deps do [ {:credo, "~> 1.7.5", only: [:dev, :test]}, + {:logger_json, "~> 7.0", only: [:dev, :test]}, {:ex_doc, ">= 0.32.1", only: :dev, runtime: false} ] end diff --git a/mix.lock b/mix.lock index 34d76e3..18a12da 100644 --- a/mix.lock +++ b/mix.lock @@ -5,6 +5,7 @@ "ex_doc": {:hex, :ex_doc, "0.32.1", "21e40f939515373bcdc9cffe65f3b3543f05015ac6c3d01d991874129d173420", [:mix], [{:earmark_parser, "~> 1.4.39", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_c, ">= 0.1.1", [hex: :makeup_c, repo: "hexpm", optional: true]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1", [hex: :makeup_erlang, repo: "hexpm", optional: false]}], "hexpm", "5142c9db521f106d61ff33250f779807ed2a88620e472ac95dc7d59c380113da"}, "file_system": {:hex, :file_system, "1.0.0", "b689cc7dcee665f774de94b5a832e578bd7963c8e637ef940cd44327db7de2cd", [:mix], [], "hexpm", "6752092d66aec5a10e662aefeed8ddb9531d79db0bc145bb8c40325ca1d8536d"}, "jason": {:hex, :jason, "1.4.1", "af1504e35f629ddcdd6addb3513c3853991f694921b1b9368b0bd32beb9f1b63", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "fbb01ecdfd565b56261302f7e1fcc27c4fb8f32d56eab74db621fc154604a7a1"}, + "logger_json": {:hex, :logger_json, "7.0.4", "e315f2b9a755504658a745f3eab90d88d2cd7ac2ecfd08c8da94d8893965ab5c", [:mix], [{:decimal, ">= 0.0.0", [hex: :decimal, repo: "hexpm", optional: true]}, {:ecto, "~> 3.11", [hex: :ecto, repo: "hexpm", optional: true]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: true]}, {:plug, "~> 1.15", [hex: :plug, repo: "hexpm", optional: true]}, {:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "d1369f8094e372db45d50672c3b91e8888bcd695fdc444a37a0734e96717c45c"}, "makeup": {:hex, :makeup, "1.1.1", "fa0bc768698053b2b3869fa8a62616501ff9d11a562f3ce39580d60860c3a55e", [:mix], [{:nimble_parsec, "~> 1.2.2 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "5dc62fbdd0de44de194898b6710692490be74baa02d9d108bc29f007783b0b48"}, "makeup_elixir": {:hex, :makeup_elixir, "0.16.2", "627e84b8e8bf22e60a2579dad15067c755531fea049ae26ef1020cad58fe9578", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "41193978704763f6bbe6cc2758b84909e62984c7752b3784bd3c218bb341706b"}, "makeup_erlang": {:hex, :makeup_erlang, "0.1.5", "e0ff5a7c708dda34311f7522a8758e23bfcd7d8d8068dc312b5eb41c6fd76eba", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "94d2e986428585a21516d7d7149781480013c56e30c6a233534bedf38867a59a"}, diff --git a/test/logger_file_backend_test.exs b/test/logger_file_backend_test.exs index 01d794a..8efa46c 100644 --- a/test/logger_file_backend_test.exs +++ b/test/logger_file_backend_test.exs @@ -2,51 +2,48 @@ defmodule LoggerFileBackendTest do use ExUnit.Case, async: false require Logger - @backend {LoggerFileBackend, :test} - @basedir "test/logs" + @moduletag :tmp_dir + @moduletag capture_log: true import LoggerFileBackend, only: [prune: 1, metadata_matches?: 2] - setup_all do - on_exit(fn -> - File.rm_rf!(@basedir) - end) - end - setup context do + backend = {LoggerFileBackend, context.test} # We add and remove the backend here to avoid cross-test effects - Logger.add_backend(@backend, flush: true) + Logger.add_backend(backend, flush: true) - config(path: logfile(context, @basedir), level: :debug) + config(Map.put(context, :backend, backend), path: logfile(context), level: :debug) on_exit(fn -> - :ok = Logger.remove_backend(@backend) + :ok = Logger.remove_backend(backend) end) + + {:ok, [backend: backend]} end - test "does not crash if path isn't set" do - config(path: nil) + test "does not crash if path isn't set", %{backend: backend} = context do + config(context, path: nil) Logger.debug("foo") - assert {:error, :already_present} = Logger.add_backend(@backend) + assert {:error, :already_present} = Logger.add_backend(backend) end - test "can configure metadata_filter" do - config(metadata_filter: [md_key: true]) + test "can configure metadata_filter", context do + config(context, metadata_filter: [md_key: true]) Logger.debug("shouldn't", md_key: false) Logger.debug("should", md_key: true) - refute log() =~ "shouldn't" - assert log() =~ "should" - config(metadata_filter: nil) + refute log(context) =~ "shouldn't" + assert log(context) =~ "should" + config(context, metadata_filter: nil) end - test "can configure metadata_reject" do - config(metadata_reject: [md_key: false]) + test "can configure metadata_reject", context do + config(context, metadata_reject: [md_key: false]) Logger.debug("shouldn't", md_key: false) Logger.debug("should", md_key: true) - refute log() =~ "shouldn't" - assert log() =~ "should" - config(metadata_reject: nil) + refute log(context) =~ "shouldn't" + assert log(context) =~ "should" + config(context, metadata_reject: nil) end test "metadata_matches?" do @@ -66,16 +63,16 @@ defmodule LoggerFileBackendTest do assert metadata_matches?([a: 1], b: 1, a: 1) == false end - test "creates log file" do - refute File.exists?(path()) + test "creates log file", context do + refute File.exists?(path(context)) Logger.debug("this is a msg") - assert File.exists?(path()) - assert log() =~ "this is a msg" + assert File.exists?(path(context)) + assert log(context) =~ "this is a msg" end - test "can log utf8 chars" do + test "can log utf8 chars", context do Logger.debug("ß\uFFaa\u0222") - assert log() =~ "ßﾪȢ" + assert log(context) =~ "ßﾪȢ" end test "prune/1" do @@ -86,89 +83,99 @@ defmodule LoggerFileBackendTest do assert prune([[] | []]) == [[]] end - test "prunes invalid utf-8 codepoints" do + test "prunes invalid utf-8 codepoints", context do Logger.debug(<<"hi", 233>>) - assert log() =~ "hi�" + assert log(context) =~ "hi�" end - test "can configure format" do - config(format: "$message [$level]\n") + test "can configure format", context do + config(context, format: "$message [$level]\n") Logger.debug("hello") - assert log() =~ "hello [debug]" + assert log(context) =~ "hello [debug]" + end + + test "can configure custom formatter", context do + formatter = LoggerJSON.Formatters.Basic.new(metadata: [:domain, :erl_level, :module]) + config(context, formatter: formatter) + + Logger.debug("hello") + + assert log(context) =~ + ~r/{"message":"hello","metadata":{"domain":\["elixir"\],"erl_level":"debug","module":"Elixir\.LoggerFileBackendTest"},"severity":"debug","time":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z"}\n/ end - test "can configure metadata" do - config(format: "$metadata$message\n", metadata: [:user_id, :auth]) + test "can configure metadata", context do + config(context, format: "$metadata$message\n", metadata: [:user_id, :auth]) Logger.debug("hello") - assert log() =~ "hello" + assert log(context) =~ "hello" Logger.metadata(auth: true) Logger.metadata(user_id: 11) Logger.metadata(user_id: 13) Logger.debug("hello") - assert log() =~ "user_id=13 auth=true hello" + assert log(context) =~ "user_id=13 auth=true hello" end - test "can configure level" do - config(level: :info) + test "can configure level", context do + config(context, level: :info) Logger.debug("hello") - refute File.exists?(path()) + refute File.exists?(path(context)) end - test "can configure path" do + test "can configure path", context do new_path = "test/logs/test.log.2" - config(path: new_path) - assert new_path == path() + config(context, path: new_path) + assert new_path == path(context) end - test "logs to new file after old file has been moved" do - config(format: "$message\n") + test "logs to new file after old file has been moved", context do + config(context, format: "$message\n") Logger.debug("foo") Logger.debug("bar") - assert log() == "foo\nbar\n" + assert log(context) == "foo\nbar\n" - {"", 0} = System.cmd("mv", [path(), path() <> ".1"]) + {"", 0} = System.cmd("mv", [path(context), path(context) <> ".1"]) Logger.debug("biz") Logger.debug("baz") - assert log() == "biz\nbaz\n" + assert log(context) == "biz\nbaz\n" end - test "closes old log file after log file has been moved" do + test "closes old log file after log file has been moved", context do Logger.debug("foo") - assert has_open(path()) + assert has_open(path(context)) - new_path = path() <> ".1" - {"", 0} = System.cmd("mv", [path(), new_path]) + new_path = path(context) <> ".1" + {"", 0} = System.cmd("mv", [path(context), new_path]) assert has_open(new_path) Logger.debug("bar") - assert has_open(path()) + assert has_open(path(context)) refute has_open(new_path) end - test "closes old log file after path has been changed" do + test "closes old log file after path has been changed", context do Logger.debug("foo") - assert has_open(path()) + assert has_open(path(context)) - org_path = path() - config(path: path() <> ".new") + org_path = path(context) + config(context, path: path(context) <> ".new") Logger.debug("bar") - assert has_open(path()) + assert has_open(path(context)) refute has_open(org_path) end - test "log file rotate" do - config(format: "$message\n") - config(rotate: %{max_bytes: 4, keep: 4}) + test "log file rotate", context do + config(context, format: "$message\n") + config(context, rotate: %{max_bytes: 4, keep: 4}) Logger.debug("rotate1") Logger.debug("rotate2") @@ -177,7 +184,7 @@ defmodule LoggerFileBackendTest do Logger.debug("rotate5") Logger.debug("rotate6") - p = path() + p = path(context) assert File.read!("#{p}.4") == "rotate2\n" assert File.read!("#{p}.3") == "rotate3\n" @@ -185,37 +192,37 @@ defmodule LoggerFileBackendTest do assert File.read!("#{p}.1") == "rotate5\n" assert File.read!(p) == "rotate6\n" - config(rotate: nil) + config(context, rotate: nil) end - test "log file not rotate" do - config(format: "$message\n") - config(rotate: %{max_bytes: 100, keep: 4}) + test "log file not rotate", context do + config(context, format: "$message\n") + config(context, rotate: %{max_bytes: 100, keep: 4}) words = ~w(rotate1 rotate2 rotate3 rotate4 rotate5 rotate6) words |> Enum.map(&Logger.debug(&1)) - assert log() == Enum.join(words, "\n") <> "\n" + assert log(context) == Enum.join(words, "\n") <> "\n" - config(rotate: nil) + config(context, rotate: nil) end - test "Allow :all to metadata" do - config(format: "$metadata") + test "Allow :all to metadata", context do + config(context, format: "$metadata") - config(metadata: []) + config(context, metadata: []) Logger.debug("metadata", metadata1: "foo", metadata2: "bar") - assert log() == "" + assert log(context) == "" - config(metadata: [:metadata3]) + config(context, metadata: [:metadata3]) Logger.debug("metadata", metadata3: "foo", metadata4: "bar") - assert log() == "metadata3=foo " + assert log(context) == "metadata3=foo " - config(metadata: :all) + config(context, metadata: :all) Logger.debug("metadata", metadata5: "foo", metadata6: "bar") # Match separately for metadata5/metadata6 to avoid depending on order - contents = log() + contents = log(context) assert contents =~ "metadata5=foo" assert contents =~ "metadata6=bar" end @@ -225,7 +232,7 @@ defmodule LoggerFileBackendTest do end defp has_open({:unix, _}, path) do - case System.cmd("lsof", [path]) do + case System.cmd("lsof", ["-w", path]) do {output, 0} -> output =~ System.pid() @@ -238,22 +245,22 @@ defmodule LoggerFileBackendTest do false end - defp path do - {:ok, path} = :gen_event.call(Logger, @backend, :path) + defp path(%{backend: backend}) do + {:ok, path} = :gen_event.call(Logger, backend, :path) path end - defp log do - File.read!(path()) + defp log(context) do + File.read!(path(context)) end - defp config(opts) do - :ok = Logger.configure_backend(@backend, opts) + defp config(%{backend: backend}, opts) do + :ok = Logger.configure_backend(backend, opts) end - defp logfile(context, basedir) do + defp logfile(%{tmp_dir: basedir, test: test_name}) do logfile = - context.test + test_name |> Atom.to_string() |> String.replace(" ", "_")