Merge pull request #184 from tuncer/logging

Fix log levels

11 files changed, 158 insertions, 37 deletions

diff --git a/ebin/rebar.app b/ebin/rebar.app
index e64a51f..873be18 100644
--- a/ebin/rebar.app
+++ b/ebin/rebar.app
@@ -50,7 +50,7 @@
                   tools]},
   {env, [
          %% Default log level
-         {log_level, error},
+         {log_level, warn},
 
          %% any_dir processing modules
          {any_dir_modules, [
diff --git a/include/rebar.hrl b/include/rebar.hrl
index 58debfc..b19fdd3 100644
--- a/include/rebar.hrl
+++ b/include/rebar.hrl
@@ -9,6 +9,6 @@
 -define(DEBUG(Str, Args), rebar_log:log(debug, Str, Args)).
 -define(INFO(Str, Args), rebar_log:log(info, Str, Args)).
 -define(WARN(Str, Args), rebar_log:log(warn, Str, Args)).
--define(ERROR(Str, Args), rebar_log:log(error, Str, Args)).
+-define(ERROR(Str, Args), rebar_log:log(standard_error, error, Str, Args)).
 
 -define(FMT(Str, Args), lists:flatten(io_lib:format(Str, Args))).
diff --git a/inttest/logging/logging_rt.erl b/inttest/logging/logging_rt.erl
new file mode 100644
index 0000000..2b8e54b
--- /dev/null
+++ b/inttest/logging/logging_rt.erl
@@ -0,0 +1,99 @@
+-module(logging_rt).
+-export([files/0,
+         run/1]).
+
+-define(APP_FILE, "ebin/logging.app").
+
+files() ->
+    [
+     {copy, "../../rebar", "rebar"},
+     {create, ?APP_FILE, app(invalid_name, [])}
+    ].
+
+run(_Dir) ->
+    SharedExpected = "==> logging_rt \\(compile\\)",
+    %% provoke ERROR due to an invalid app file
+    retest:log(info, "Check 'compile' failure output~n"),
+    ok = check_output("./rebar compile -q", should_fail,
+                      [SharedExpected, "ERROR: "],
+                      ["WARN: ", "INFO: ", "DEBUG: "]),
+    %% fix bad app file
+    ok = file:write_file(?APP_FILE, app(logging, [])),
+    retest:log(info, "Check 'compile' success output~n"),
+    ok = check_output("./rebar compile", should_succeed,
+                      [SharedExpected],
+                      ["ERROR: ", "WARN: ", "INFO: ", "DEBUG: "]),
+    retest:log(info, "Check 'compile -v' success output~n"),
+    ok = check_output("./rebar compile -v", should_succeed,
+                      [SharedExpected],
+                      ["ERROR: ", "INFO: ", "DEBUG: "]),
+    retest:log(info, "Check 'compile -vv' success output~n"),
+    ok = check_output("./rebar compile -vv", should_succeed,
+                      [SharedExpected, "DEBUG: "],
+                      ["ERROR: ", "INFO: "]),
+    ok.
+
+check_output(Cmd, FailureMode, Expected, Unexpected) ->
+    case {retest:sh(Cmd), FailureMode} of
+        {{error, _}=Error, should_succeed} ->
+            retest:log(error, "cmd '~s' failed:~n~p~n", [Cmd, Error]),
+            Error;
+        {{ok, Captured}, should_succeed} ->
+            Joined = string:join(Captured, "\n"),
+            check_output1(Cmd, Joined, Expected, Unexpected);
+        {{error, {stopped, {_Rc, Captured}}}, should_fail} ->
+            Joined = string:join(Captured, "\n"),
+            check_output1(Cmd, Joined, Expected, Unexpected)
+    end.
+
+check_output1(Cmd, Captured, Expected, Unexpected) ->
+    ReOpts = [{capture, all, list}],
+    ExMatches =
+        lists:zf(
+          fun(Pattern) ->
+                  case re:run(Captured, Pattern, ReOpts) of
+                      nomatch ->
+                          retest:log(error,
+                                     "Expected pattern '~s' missing "
+                                     "in the following output:~n"
+                                     "=== BEGIN ===~n~s~n=== END ===~n",
+                                     [Pattern, Captured]),
+                          {true, Pattern};
+                      {match, _} ->
+                          false
+                  end
+          end, Expected),
+
+    UnExMatches =
+        lists:zf(
+          fun(Pattern) ->
+                  case re:run(Captured, Pattern, ReOpts) of
+                      nomatch ->
+                          false;
+                      {match, [Match]} ->
+                          retest:log(
+                            console,
+                            "Unexpected output when running cmd '~s':~n~s~n",
+                            [Cmd, Match]),
+                          {true, Match}
+                  end
+          end, Unexpected),
+
+    case {ExMatches, UnExMatches} of
+        {[], []} ->
+            ok;
+        _ ->
+            error
+    end.
+
+%%
+%% Generate the contents of a simple .app file
+%%
+app(Name, Modules) ->
+    App = {application, Name,
+           [{description, atom_to_list(Name)},
+            {vsn, "1"},
+            {modules, Modules},
+            {registered, []},
+            {applications, [kernel, stdlib]}]},
+    io_lib:format("~p.\n", [App]).
diff --git a/inttest/t_custom_config/t_custom_config_rt.erl b/inttest/t_custom_config/t_custom_config_rt.erl
index 864ce5e..b56eb1a 100644
--- a/inttest/t_custom_config/t_custom_config_rt.erl
+++ b/inttest/t_custom_config/t_custom_config_rt.erl
@@ -11,7 +11,7 @@ files() ->
 
 run(Dir) ->
     retest_log:log(debug, "Running in Dir: ~s~n", [Dir]),
-    Ref = retest:sh("./rebar -C custom.config check-deps -vvv",
+    Ref = retest:sh("./rebar -C custom.config check-deps -vv",
                     [{async, true}]),
     {ok, Captured} =
         retest:sh_expect(Ref,
diff --git a/priv/shell-completion/zsh/_rebar b/priv/shell-completion/zsh/_rebar
index 3d04ba1..21d9a8a 100644
--- a/priv/shell-completion/zsh/_rebar
+++ b/priv/shell-completion/zsh/_rebar
@@ -7,10 +7,10 @@ _rebar_global_opts=(
   '(--help -h)'{--help,-h}'[Show the program options]'
   '(--commands -c)'{--commands,-c}'[Show available commands]'
   '(--version -V)'{--version,-V}'[Show version information]'
-  '(-vvv -vv -v)'--verbose+'[Verbosity level. Default: 0]:verbosity level:(0 1 2 3)'
-  '(-vvv)-v[Slightly more verbose output]'
-  '(-vvv)-vv[More verbose output]'
-  '(-v -vv)-vvv[Most verbose output]'
+  '(-vv -v)'--verbose'[Enforce verbosity level]'
+  '(-vv)-v[Slightly more verbose output]'
+  '(-v)-vv[More verbose output]'
+  '(-vv -v --verbose)'{--quiet,-q}'[Quiet, only print error messages]'
   '(--force -f)'{--force,-f}'[Force]'
   '-D+[Define compiler macro]'
   '(--jobs -j)'{--jobs+,-j+}'[Number of concurrent workers a command may use. Default: 3]:workers:(1 2 3 4 5 6 7 8 9)'
diff --git a/src/rebar.erl b/src/rebar.erl
index 2d9fe04..8fad12f 100644
--- a/src/rebar.erl
+++ b/src/rebar.erl
@@ -258,13 +258,27 @@ save_options(Config, {Options, NonOptArgs}) ->
 %% set log level based on getopt option
 %%
 set_log_level(Config, Options) ->
-    LogLevel = case proplists:get_all_values(verbose, Options) of
-                   [] ->
-                       rebar_log:default_level();
-                   Verbosities ->
-                       lists:last(Verbosities)
-               end,
-    rebar_config:set_global(Config, verbose, LogLevel).
+    {IsVerbose, Level} =
+        case proplists:get_bool(quiet, Options) of
+            true ->
+                {false, rebar_log:error_level()};
+            false ->
+                DefaultLevel = rebar_log:default_level(),
+                case proplists:get_all_values(verbose, Options) of
+                    [] ->
+                        {false, DefaultLevel};
+                    Verbosities ->
+                        {true, DefaultLevel + lists:last(Verbosities)}
+                end
+        end,
+
+    case IsVerbose of
+        true ->
+            Config1 = rebar_config:set_xconf(Config, is_verbose, true),
+            rebar_config:set_global(Config1, verbose, Level);
+        false ->
+            rebar_config:set_global(Config, verbose, Level)
+    end.
 
 %%
 %% show version information and halt
@@ -375,12 +389,12 @@ option_spec_list() ->
     JobsHelp = io_lib:format(
                  "Number of concurrent workers a command may use. Default: ~B",
                  [Jobs]),
-    VerboseHelp = "Verbosity level (-v, -vv, -vvv, --verbose 3). Default: 0",
     [
      %% {Name, ShortOpt, LongOpt, ArgSpec, HelpMsg}
      {help,     $h, "help",     undefined, "Show the program options"},
      {commands, $c, "commands", undefined, "Show available commands"},
-     {verbose,  $v, "verbose",  integer,   VerboseHelp},
+     {verbose,  $v, "verbose",  integer,   "Verbosity level (-v, -vv)"},
+     {quiet,    $q, "quiet",    boolean,   "Quiet, only print error messages"},
      {version,  $V, "version",  undefined, "Show version information"},
      {force,    $f, "force",    undefined, "Force"},
      {defines,  $D, undefined,  string,    "Define compiler macro"},
diff --git a/src/rebar_config.erl b/src/rebar_config.erl
index 461de5d..9b58d4f 100644
--- a/src/rebar_config.erl
+++ b/src/rebar_config.erl
@@ -31,7 +31,6 @@
          get_all/2,
          set/3,
          set_global/3, get_global/3,
-         is_verbose/1,
          save_env/3, get_env/2, reset_envs/1,
          set_skip_dir/2, is_skip_dir/2, reset_skip_dirs/1,
          clean_config/2,
@@ -110,10 +109,6 @@ get_global(Config, Key, Default) ->
             Value
     end.
 
-is_verbose(Config) ->
-    DefaulLevel = rebar_log:default_level(),
-    get_global(Config, verbose, DefaulLevel) > DefaulLevel.
-
 consult_file(File) ->
     case filename:extension(File) of
         ".script" ->
diff --git a/src/rebar_ct.erl b/src/rebar_ct.erl
index 74ae618..91d763b 100644
--- a/src/rebar_ct.erl
+++ b/src/rebar_ct.erl
@@ -101,7 +101,7 @@ run_test(TestDir, LogDir, Config, _File) ->
     {Cmd, RawLog} = make_cmd(TestDir, LogDir, Config),
     ?DEBUG("ct_run cmd:~n~p~n", [Cmd]),
     clear_log(LogDir, RawLog),
-    Output = case rebar_config:is_verbose(Config) of
+    Output = case rebar_log:is_verbose(Config) of
                  false ->
                      " >> " ++ RawLog ++ " 2>&1";
                  true ->
@@ -172,7 +172,7 @@ check_log(Config,RawLog,Fun) ->
 %% Show the log if it hasn't already been shown because verbose was on
 show_log(Config, RawLog) ->
     ?CONSOLE("Showing log\n", []),
-    case rebar_config:is_verbose(Config) of
+    case rebar_log:is_verbose(Config) of
         false ->
             {ok, Contents} = file:read_file(RawLog),
             ?CONSOLE("~s", [Contents]);
diff --git a/src/rebar_eunit.erl b/src/rebar_eunit.erl
index d39b1a2..6ea28f7 100644
--- a/src/rebar_eunit.erl
+++ b/src/rebar_eunit.erl
@@ -408,7 +408,7 @@ perform_eunit(Config, Tests) ->
 
 get_eunit_opts(Config) ->
     %% Enable verbose in eunit if so requested..
-    BaseOpts = case rebar_config:is_verbose(Config) of
+    BaseOpts = case rebar_log:is_verbose(Config) of
                    true ->
                        [verbose];
                    false ->
diff --git a/src/rebar_log.erl b/src/rebar_log.erl
index 4108c9c..ba25332 100644
--- a/src/rebar_log.erl
+++ b/src/rebar_log.erl
@@ -27,8 +27,17 @@
 -module(rebar_log).
 
 -export([init/1,
-         set_level/1, default_level/0,
-         log/3]).
+         set_level/1,
+         error_level/0,
+         default_level/0,
+         log/3,
+         log/4,
+         is_verbose/1]).
+
+-define(ERROR_LEVEL, 0).
+-define(WARN_LEVEL,  1).
+-define(INFO_LEVEL,  2).
+-define(DEBUG_LEVEL, 3).
 
 %% ===================================================================
 %% Public API
@@ -37,35 +46,39 @@
 init(Config) ->
     Verbosity = rebar_config:get_global(Config, verbose, default_level()),
     case valid_level(Verbosity) of
-        0 -> set_level(error);
-        1 -> set_level(warn);
-        2 -> set_level(info);
-        3 -> set_level(debug)
+        ?ERROR_LEVEL -> set_level(error);
+        ?WARN_LEVEL  -> set_level(warn);
+        ?INFO_LEVEL  -> set_level(info);
+        ?DEBUG_LEVEL -> set_level(debug)
     end.
 
 set_level(Level) ->
     ok = application:set_env(rebar, log_level, Level).
 
 log(Level, Str, Args) ->
+    log(standard_io, Level, Str, Args).
+
+log(Device, Level, Str, Args) ->
     {ok, LogLevel} = application:get_env(rebar, log_level),
     case should_log(LogLevel, Level) of
         true ->
-            io:format(log_prefix(Level) ++ Str, Args);
+            io:format(Device, log_prefix(Level) ++ Str, Args);
         false ->
             ok
     end.
 
-default_level() -> error_level().
+error_level() -> ?ERROR_LEVEL.
+default_level() -> ?WARN_LEVEL.
+
+is_verbose(Config) ->
+    rebar_config:get_xconf(Config, is_verbose, false).
 
 %% ===================================================================
 %% Internal functions
 %% ===================================================================
 
 valid_level(Level) ->
-    erlang:max(error_level(), erlang:min(Level, debug_level())).
-
-error_level() -> 0.
-debug_level() -> 3.
+    erlang:max(?ERROR_LEVEL, erlang:min(Level, ?DEBUG_LEVEL)).
 
 should_log(debug, _)     -> true;
 should_log(info, debug)  -> false;
diff --git a/src/rebar_xref.erl b/src/rebar_xref.erl
index eaf6d03..0d89460 100644
--- a/src/rebar_xref.erl
+++ b/src/rebar_xref.erl
@@ -51,7 +51,7 @@ xref(Config, _) ->
 
     xref:set_default(xref, [{warnings,
                              rebar_config:get(Config, xref_warnings, false)},
-                            {verbose, rebar_config:is_verbose(Config)}]),
+                            {verbose, rebar_log:is_verbose(Config)}]),
 
     {ok, _} = xref:add_directory(xref, "ebin"),