diff --git a/README.md b/README.md index 536bed6..2f795a0 100644 --- a/README.md +++ b/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 diff --git a/lib/logger.ex b/lib/logger.ex index 1a9ef26..af4194f 100644 --- a/lib/logger.ex +++ b/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}" diff --git a/lib/strategy/dns_poll.ex b/lib/strategy/dns_poll.ex index d1f7ec9..acd6b09 100644 --- a/lib/strategy/dns_poll.ex +++ b/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 diff --git a/lib/strategy/kubernetes.ex b/lib/strategy/kubernetes.ex index b665e25..b687666 100644 --- a/lib/strategy/kubernetes.ex +++ b/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) diff --git a/lib/strategy/kubernetes_dns.ex b/lib/strategy/kubernetes_dns.ex index 9a4568a..1957c96 100644 --- a/lib/strategy/kubernetes_dns.ex +++ b/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)}") diff --git a/lib/strategy/kubernetes_dns_srv.ex b/lib/strategy/kubernetes_dns_srv.ex index f636795..abef0ba 100644 --- a/lib/strategy/kubernetes_dns_srv.ex +++ b/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( diff --git a/lib/strategy/rancher.ex b/lib/strategy/rancher.ex index d64e934..12adca3 100644 --- a/lib/strategy/rancher.ex +++ b/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( diff --git a/test/logger_test.exs b/test/logger_test.exs index 6862aed..14caa3f 100644 --- a/test/logger_test.exs +++ b/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