Add more debugging messages

README.md

@@ -138,6 +138,21 @@ but are known to exist.
 - [libcluster_ec2](https://github.com/kyleaa/libcluster_ec2) - EC2 clustering strategy based on tags
 - [libcluster_consul](https://github.com/team-telnyx/libcluster_consul) - Consul clustering strategy
 
+## Debugging
+
+You can enable debugging messages from `libcluster` in your config files, by doing:
+
+```elixir
+config :libcluster, :debug, true
+```
+
+Alternatively, a numerical value can be also configured (e.g. `1` .. `5`).
+This numerical value represent the level of verbosity for the debugging logs.
+Level 1 is already very verbose, but things get worse the bigger this level is.
+Level 2 is usually used to log the names of the discovered nodes, while level 5
+will even log intermediate values used by the strategies (e.g. REST API
+responses for `Kubernetes`/`Rancher` strategies).
+
 ## License
 
 MIT

lib/logger.ex

@@ -2,11 +2,17 @@ defmodule Cluster.Logger do
   @moduledoc false
   require Logger
 
-  def debug(t, msg) do
+
+  def debug(t, msg, verbosity_level \\ 1)
+  def debug(t, msg, verbose: verbosity_level), do: debug(t, msg, verbosity_level)
+  def debug(t, msg, verbosity_level) do
     case Application.get_env(:libcluster, :debug, false) do
       dbg when dbg in [nil, false, "false"] ->
         :ok
 
+      verbose when is_integer(verbose) and verbose < verbosity_level ->
+        :ok
+
       _ ->
         Logger.debug(log_message(t, msg))
     end
@@ -16,6 +22,27 @@ defmodule Cluster.Logger do
   def warn(t, msg), do: Logger.warn(log_message(t, msg))
   def error(t, msg), do: Logger.error(log_message(t, msg))
 
+  @doc """
+  Hybrid between `Kernel.inspect/2` and `debug/2`.
+
+  Similarly to `IO.inspect`, it makes possible to `spy` on a value,
+  while returning it unchanged.
+
+  Please note that the second argument is send as first argument to `debug/2`
+  while the first argument is printed to the log handler via `Kernel.inspect/2`.
+  This function also accepts a `:label` option (similarly to `IO.inspect/2`),
+  and a `:verbose` option (by default: `verbose = 1`, the message is suppressed
+  when `verbose < Application.get_env(:libcluster, :debug)`), but all the other
+  options are forwarded to `Kernel.inspect/2`.
+  """
+  def debug_inspect(value, t, opts \\ []) do
+    {label, opts} = Keyword.pop(opts, :label, nil)
+    {verbose, opts} = Keyword.pop(opts, :verbose, 1)
+    label = if label, do: "#{label}: ", else: ""
+    debug(t, "#{label}#{inspect(value, opts)}", verbose: verbose)
+    value
+  end
+
   @compile {:inline, log_message: 2}
   defp log_message(t, msg) do
     "[libcluster:#{t}] #{msg}"

lib/strategy/dns_poll.ex

@@ -101,7 +101,7 @@ defmodule Cluster.Strategy.DNSPoll do
     Keyword.get(config, :polling_interval, @default_polling_interval)
   end
 
-  defp get_nodes(%State{config: config} = state) do
+  defp get_nodes(%State{topology: topology, config: config} = state) do
     query = Keyword.fetch(config, :query)
     node_basename = Keyword.fetch(config, :node_basename)
 
@@ -113,6 +113,7 @@ defmodule Cluster.Strategy.DNSPoll do
       end)
 
     resolve(query, node_basename, resolver, state)
+    |> debug_inspect(topology, label: "node names", verbose: 2)
   end
 
   # query for all ips responding to a given dns query

lib/strategy/kubernetes.ex

@@ -208,6 +208,7 @@ defmodule Cluster.Strategy.Kubernetes do
     selector = Keyword.fetch!(config, :kubernetes_selector)
     ip_lookup_mode = Keyword.get(config, :kubernetes_ip_lookup_mode, :endpoints)
     master = Keyword.get(config, :kubernetes_master, @kubernetes_master)
+    mode = Keyword.get(config, :mode, :ip)
 
     cond do
       app_name != nil and selector != nil ->
@@ -224,16 +225,13 @@ defmodule Cluster.Strategy.Kubernetes do
 
         case :httpc.request(:get, {'https://#{master}/#{path}', headers}, http_options, []) do
           {:ok, {{_version, 200, _status}, _headers, body}} ->
-            parse_response(ip_lookup_mode, Jason.decode!(body))
-            |> Enum.map(fn node_info ->
-              format_node(
-                Keyword.get(config, :mode, :ip),
-                node_info,
-                app_name,
-                cluster_name,
-                service_name
-              )
-            end)
+            body
+            |> Jason.decode!
+            |> debug_inspect(topology, label: "Kubernetes API", pretty: true, verbose: 5)
+            |> (&parse_response(ip_lookup_mode, &1)).()
+            |> debug_inspect(topology, label: "detected nodes", pretty: true, verbose: 3)
+            |> Enum.map(&format_node(mode, &1, app_name, cluster_name, service_name))
+            |> debug_inspect(topology, label: "node names", pretty: true, verbose: 2)
 
           {:ok, {{_version, 403, _status}, _headers, body}} ->
             %{"message" => msg} = Jason.decode!(body)

lib/strategy/kubernetes_dns.ex

@@ -117,6 +117,7 @@ defmodule Cluster.Strategy.Kubernetes.DNS do
         case resolver.(headless_service) do
           {:ok, {:hostent, _fqdn, [], :inet, _value, addresses}} ->
             parse_response(addresses, app_name)
+            |> debug_inspect(topology, label: "node names", pretty: true, verbose: 2)
 
           {:error, reason} ->
             error(topology, "lookup against #{service} failed: #{inspect(reason)}")

lib/strategy/kubernetes_dns_srv.ex

@@ -197,6 +197,7 @@ defmodule Cluster.Strategy.Kubernetes.DNSSRV do
         case resolver.(headless_service) do
           {:ok, {:hostent, _, _, :srv, _count, addresses}} ->
             parse_response(addresses, app_name)
+            |> debug_inspect(topology, label: "node names", verbose: 2)
 
           {:error, reason} ->
             error(

lib/strategy/rancher.ex

@@ -135,7 +135,11 @@ defmodule Cluster.Strategy.Rancher do
                []
              ) do
           {:ok, {{_version, 200, _status}, _headers, body}} ->
-            parse_response(app_name, Jason.decode!(body))
+            body
+            |> Jason.decode!
+            |> debug_inspect(topology, label: "Rancher API", pretty: true, verbose: 5)
+            |> (&parse_response(app_name, &1)).()
+            |> debug_inspect(topology, label: "node names", verbose: 2)
 
           {:ok, {{_version, code, status}, _headers, body}} ->
             warn(

test/logger_test.exs

@@ -24,4 +24,37 @@ defmodule Cluster.LoggerTest do
       end
     end
   end
+
+  describe "debug_inspect/2" do
+    setup do
+      Application.put_env(:libcluster, :debug, 1)
+    end
+
+    test "with label" do
+      output =
+        capture_log(fn ->
+          %{foo: "bar"} |> Logger.debug_inspect(__MODULE__, label: "value")
+        end)
+
+      assert output =~ ~s|[libcluster:Elixir.Cluster.LoggerTest] value: %{foo: "bar"}|
+    end
+
+    test "without label" do
+      output =
+        capture_log(fn ->
+          %{foo: "bar"} |> Logger.debug_inspect(__MODULE__)
+        end)
+
+      assert output =~ ~s|[libcluster:Elixir.Cluster.LoggerTest] %{foo: "bar"}|
+    end
+
+    test "ignore if level is too low" do
+      output =
+        capture_log(fn ->
+          %{foo: "bar"} |> Logger.debug_inspect(__MODULE__, label: "value", verbose: 2)
+        end)
+
+      assert output == ""
+    end
+  end
 end