Allowed logging of errors to be quieted. (#165)

* Allowed logging of errors to be quieted.

While using elixir-ls, frequently, the code that's sent to the LSP
server (and then to elixir_sense) isn't always syntactically accurate,
and sometimes elixir_sense will fail and spam the logs. After enough
of these spammy logs, emacs throws the error into a mini-buffer to
alert the user to some problem, which is not particularly helpful.

Emitting an error message in these circumstances is dubious, since
there's nothing truly wrong, but I can understand that it might be
helpful for other uses of elixir_ls. To that end, I consolidated the
logging functions into a module and gated them with an application
variable so that other apps can enable or disable logging at their
discretion.

* Moved to macros

I was thinking about the prior implementation, and I think it would
mess up the line and files due to it calling a function in the Log
module. Making pass through macros surrounded by an if simplifies
things greatly.

* elixir 1.11 puts an additional space after info. Updating unit test

config/config.exs

@@ -0,0 +1,6 @@
+import  Config
+
+config :elixir_sense,
+  logging_enabled: true
+
+import_config "#{Mix.env()}.exs"

config/dev.exs

@@ -0,0 +1 @@
+import Config

config/prod.exs

@@ -0,0 +1,2 @@
+import Config
+config :elixir_sense, logging_enabled: false

config/test.exs

@@ -0,0 +1 @@
+import Config

lib/elixir_sense/core/ast.ex

@@ -5,6 +5,7 @@ defmodule ElixirSense.Core.Ast do
 
   alias ElixirSense.Core.Introspection
   alias ElixirSense.Core.State
+  import ElixirSense.Log
 
   @empty_env_info %{
     requires: [],
@@ -72,7 +73,7 @@ defmodule ElixirSense.Core.Ast do
     env_info
   catch
     {:expand_error, _} ->
-      IO.puts(:stderr, "Info: ignoring recursive macro")
+      info("ignoring recursive macro")
       @empty_env_info
   end
 

lib/elixir_sense/core/metadata_builder.ex

@@ -4,6 +4,8 @@ defmodule ElixirSense.Core.MetadataBuilder do
   """
 
   import ElixirSense.Core.State
+  import ElixirSense.Log
+
   alias ElixirSense.Core.Ast
   alias ElixirSense.Core.BuiltinFunctions
   alias ElixirSense.Core.Introspection
@@ -54,9 +56,12 @@ defmodule ElixirSense.Core.MetadataBuilder do
         fun.(ast, state)
       rescue
         exception ->
-          IO.warn(
-            "#{inspect(exception.__struct__)} during metadata build: #{Exception.message(exception)}",
-            __STACKTRACE__
+          warn(
+            Exception.format(
+              :error,
+              "#{inspect(exception.__struct__)} during metadata build: #{Exception.message(exception)}",
+              __STACKTRACE__
+            )
           )
 
           {nil, state}

lib/elixir_sense/log.ex

@@ -0,0 +1,40 @@
+defmodule ElixirSense.Log do
+  @moduledoc """
+  A simple logger for the project that allows it to be muted via application config
+  """
+  require Logger
+
+  def enabled? do
+    Application.get_env(:elixir_sense, :logging_enabled, true)
+  end
+
+  defmacro info(message) do
+    quote do
+      require Logger
+
+      if ElixirSense.Log.enabled?() do
+        Logger.info(unquote(message))
+      end
+    end
+  end
+
+  defmacro warn(message) do
+    quote do
+      require Logger
+
+      if ElixirSense.Log.enabled?() do
+        Logger.warning(unquote(message))
+      end
+    end
+  end
+
+  defmacro error(message) when is_binary(message) do
+    quote do
+      require Logger
+
+      if ElixirSense.Log.enabled?() do
+        Logger.error(unquote(message))
+      end
+    end
+  end
+end

test/elixir_sense/log_test.exs

@@ -0,0 +1,43 @@
+defmodule ElixirSense.LogTest do
+  use ExUnit.Case
+  import ExUnit.CaptureLog
+  import ElixirSense.Log
+
+  def with_logging_disabled(_) do
+    orig_value = Application.get_env(:elixir_sense, :logging_enabled)
+    Application.put_env(:elixir_sense, :logging_enabled, false)
+    on_exit(fn -> Application.put_env(:elixir_sense, :logging_enabled, orig_value) end)
+    :ok
+  end
+
+  describe "log messages" do
+    test "an info message has an info label by default" do
+      message = assert capture_log(fn -> info("good morning") end)
+      assert message =~ "[info] "
+      assert message =~ "good morning\n"
+    end
+
+    test "an error message has an error label by default" do
+      message = assert capture_log(fn -> error("good morning") end)
+      assert message =~ "[error] "
+      assert message =~ "good morning\n"
+    end
+  end
+
+  describe "with logging disabled" do
+    setup [:with_logging_disabled]
+
+    test "info emits no output" do
+      assert capture_log(fn -> info("hello") end) == ""
+    end
+
+    test "warn emits no output" do
+      assert capture_log(fn -> warn("hello") end) == ""
+      assert capture_log(fn -> warn("hello") end) == ""
+    end
+
+    test "error emits no output" do
+      assert capture_log(fn -> error("hello") end) == ""
+    end
+  end
+end