Add tracing's EnvFilter-like log filtering with PHILOMENA_LOG env var (#495)

* Add `tracing`'s `EnvFilter`-like log filtering with `PHILOMENA_LOG` env var

* Add logs about thumbnails generation

* Better comment

* Remove nesting via `with`

* Use `debug` logging level for ecto by default as per Meow

Author: MareStare

docker-compose.yml

@@ -13,6 +13,13 @@ services:
       context: .
       dockerfile: ./docker/app/Dockerfile
     environment:
+      # Use this env variable to control the logs levels from different modules.
+      # The syntax is `{module.function}=level,...`. The filter evaluation stops
+      # on the first `{module.function}` that has a prefix match against the log
+      # event's module and function. The last entry in the list of filters should
+      # be a bare `level` which will be used as a catch-all for all other log
+      # events that do not match any of the previous filters.
+      - PHILOMENA_LOG=${PHILOMENA_LOG-Ecto=debug,Exq=none,PhilomenaMedia.Objects=info,debug}
       - MIX_ENV=dev
       - PGPASSWORD=postgres
       - ANONYMOUS_NAME_SALT=2fmJRo0OgMFe65kyAJBxPT0QtkVes/jnKDdtP21fexsRqiw8TlSY7yO+uFyMZycp

lib/philomena/application.ex

@@ -6,6 +6,8 @@ defmodule Philomena.Application do
   use Application
 
   def start(_type, _args) do
+    configure_logging()
+
     # List all child processes to be supervised
     children = [
       # Start the Ecto repository
@@ -56,4 +58,50 @@ defmodule Philomena.Application do
     do: Base.encode16(:crypto.strong_rand_bytes(6))
 
   defp valid_node_name(node), do: node
+
+  defp configure_logging() do
+    # Log filtering design is borrowed from the Rust's `tracing` observability framework.
+    # Specifically from the `EnvFilter` syntax:
+    # https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
+    # However, it implements a simpler subset of that syntax which is just prefix matching.
+    #
+    # It would also be cool to get tracing's spans model for better low-level and
+    # concurrent logs context. But spans implementation would require a lot of work,
+    # unless there is an existing library for that. Anyway, for now, this should suffice.
+    filters =
+      System.get_env("PHILOMENA_LOG", "")
+      |> String.split(",")
+      |> Enum.map(&String.trim(&1))
+      |> Enum.reject(&(&1 == ""))
+      |> Enum.map(fn directive ->
+        {selector, level} =
+          case String.split(directive, "=", parts: 2) do
+            [selector, level] -> {selector, level}
+            [level] -> {nil, level}
+          end
+
+        {selector, String.to_existing_atom(level)}
+      end)
+
+    if not Enum.empty?(filters) do
+      allow_log_event? = fn event ->
+        with {module, function, _arity} <- Map.get(event.meta, :mfa),
+             scope <- "#{inspect(module)}.#{function}",
+             {_selector, level} when not is_nil(filters) <-
+               filters
+               |> Enum.find(fn {selector, _level} ->
+                 is_nil(selector) or String.starts_with?(scope, selector)
+               end) do
+          Logger.compare_levels(event.level, level) != :lt
+        else
+          _ -> false
+        end
+      end
+
+      :logger.add_primary_filter(
+        :sql_logs,
+        {fn event, _ -> if(allow_log_event?.(event), do: :ignore, else: :stop) end, []}
+      )
+    end
+  end
 end

lib/philomena/images/thumbnailer.ex

@@ -15,6 +15,8 @@ defmodule Philomena.Images.Thumbnailer do
   alias Philomena.Images.Image
   alias Philomena.Repo
 
+  require Logger
+
   @versions [
     thumb_tiny: {50, 50},
     thumb_small: {150, 150},
@@ -75,6 +77,9 @@ defmodule Philomena.Images.Thumbnailer do
 
   def generate_thumbnails(image_id) do
     image = Repo.get!(Image, image_id)
+
+    Logger.debug("Generating thumbnails for the image #{image.id}")
+
     file = download_image_file(image)
     {:ok, analysis} = Analyzers.analyze_path(file)