From a9a80048231640cbfc6bda1669b7e87a9a5a92d0 Mon Sep 17 00:00:00 2001 From: Anderson Bravalheri Date: Fri, 29 May 2020 19:46:00 +0100 Subject: [PATCH] Add more debugging messages Although errors and warnings are being logged, some times the strategies result in empty sets of nodes. Being able to see more information in the logs is helpful to troubleshoot complex cluster systems. --- README.md | 15 ++++++++++++++ lib/logger.ex | 29 +++++++++++++++++++++++++- lib/strategy/dns_poll.ex | 3 ++- lib/strategy/kubernetes.ex | 18 ++++++++-------- lib/strategy/kubernetes_dns.ex | 1 + lib/strategy/kubernetes_dns_srv.ex | 1 + lib/strategy/rancher.ex | 6 +++++- test/logger_test.exs | 33 ++++++++++++++++++++++++++++++ 8 files changed, 93 insertions(+), 13 deletions(-) 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