Rework debug/diagnostic logs for compile tasks

This should cover most cases, including hooks.
What this specifically does is change some less useful messages for more
contextualized ones, including tying specific configurations to actions
taking place. This is particularly visible in hooks, and hopefully
provides some amount of discoverability.

Also of note:
- ebin/ directory copying is called explicitly when done since people
  have issues with that
- paths for compiled files are made relative since the analysis list
  shows the full paths already
- hooks are a bit more verbose but also more useful.

src/rebar_compiler.erl

@@ -321,21 +321,21 @@ compile_worker(Source, [Opts, Config, Outs, CompilerMod]) ->
     {Result, Source}.
 
 compile_handler({ok, Source}, _Args) ->
-    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), Source]),
+    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), filename:basename(Source)]),
     ok;
 compile_handler({{ok, Tracked}, Source}, [_, Tracking]) when Tracking ->
-    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), Source]),
+    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), filename:basename(Source)]),
     {ok, Tracked};
 compile_handler({{ok, Warnings}, Source}, _Args) ->
     report(Warnings),
-    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), Source]),
+    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), filename:basename(Source)]),
     ok;
 compile_handler({{ok, Tracked, Warnings}, Source}, [_, Tracking]) when Tracking ->
     report(Warnings),
-    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), Source]),
+    ?DEBUG("~sCompiled ~s", [rebar_utils:indent(1), filename:basename(Source)]),
     {ok, Tracked};
 compile_handler({skipped, Source}, _Args) ->
-    ?DEBUG("~sSkipped ~s", [rebar_utils:indent(1), Source]),
+    ?DEBUG("~sSkipped ~s", [rebar_utils:indent(1), filename:basename(Source)]),
     ok;
 compile_handler({Error, Source}, [Config | _Rest]) ->
     NewSource = format_error_source(Source, Config),

src/rebar_compiler_epp.erl

@@ -145,7 +145,7 @@ list_directory(Dir, Cache) ->
                         {Cache, []}, DirFiles),
                     {NewFs#{Dir => Files}, Files};
                 {error, Reason} ->
-                    ?DEBUG("Failed to list ~s, ~p", [Dir, Reason]),
+                    ?DIAGNOSTIC("Failed to list ~s, ~p", [Dir, Reason]),
                     {Cache, []}
             end
     end.

src/rebar_compiler_erl.erl

@@ -48,8 +48,8 @@ needed_files(Graph, FoundFiles, _, AppInfo) ->
     EbinDir = rebar_app_info:ebin_dir(AppInfo),
     RebarOpts = rebar_app_info:opts(AppInfo),
     ErlOpts = rebar_opts:erl_opts(RebarOpts),
-    ?DEBUG("erlopts ~p", [ErlOpts]),
-    ?DEBUG("files to compile ~p", [FoundFiles]),
+    ?DEBUG("compile options: {erl_opts, ~p}.", [ErlOpts]),
+    ?DEBUG("files to analyze ~p", [FoundFiles]),
 
     %% Make sure that the ebin dir is on the path
     ok = rebar_file_utils:ensure_dir(EbinDir),

src/rebar_hooks.erl

@@ -12,20 +12,34 @@
                    atom() | {atom(), atom()} | string(),
                    [providers:t()], rebar_app_info:t(), rebar_state:t()) -> rebar_app_info:t().
 run_all_hooks(Dir, Type, Command, Providers, AppInfo, State) ->
+    ?DEBUG("Running hooks for ~p in app ~ts (~ts) with configuration:",
+           [Command, rebar_app_info:name(AppInfo), Dir]),
     State1 = rebar_state:current_app(State, AppInfo),
     State2 = run_provider_hooks(Dir, Type, Command, Providers, rebar_app_info:opts(AppInfo), State1),
     run_hooks(Dir, Type, Command, rebar_app_info:opts(AppInfo), State1),
     rebar_state:current_app(State2).
 
 run_all_hooks(Dir, Type, Command, Providers, State) ->
+    ?DEBUG("Running hooks for ~p with configuration:", [Command]),
     run_provider_hooks(Dir, Type, Command, Providers, rebar_state:opts(State), State),
     run_hooks(Dir, Type, Command, rebar_state:opts(State), State).
 
 run_project_and_app_hooks(Dir, Type, Command, Providers, State) ->
     ProjectApps = rebar_state:project_apps(State),
+    ?DEBUG("Running app-specific hooks", []),
     [rebar_hooks:run_all_hooks(Dir, Type, Command, Providers, AppInfo, State) || AppInfo <- ProjectApps],
+    ?DEBUG("Running project-wide hooks", []),
     run_all_hooks(Dir, Type, Command, Providers, State).
 
+format_error({bad_provider, Type, Command, {Name, Namespace}}) ->
+    io_lib:format("Unable to run ~ts hooks for '~p', command '~p' in namespace '~p' not found.", [Type, Command, Namespace, Name]);
+format_error({bad_provider, Type, Command, Name}) ->
+    io_lib:format("Unable to run ~ts hooks for '~p', command '~p' not found.", [Type, Command, Name]).
+
+%%%%%%%%%%%%%%%
+%%% PRIVATE %%%
+%%%%%%%%%%%%%%%
+
 run_provider_hooks(Dir, Type, Command, Providers, Opts, State) ->
     case rebar_opts:get(Opts, provider_hooks, []) of
         [] ->
@@ -40,11 +54,14 @@ run_provider_hooks_(_Dir, _Type, _Command, _Providers, [], State) ->
 run_provider_hooks_(Dir, Type, Command, Providers, TypeHooks, State) ->
     case proplists:get_all_values(Command, TypeHooks) of
         [] ->
+            ?DEBUG("\t{provider_hooks, []}.", []),
             State;
         HookProviders ->
             rebar_paths:set_paths([plugins], State),
             Providers1 = rebar_state:providers(State),
             State1 = rebar_state:providers(rebar_state:dir(State, Dir), Providers++Providers1),
+            ?DEBUG("\t{provider_hooks, [{~p, ~p}]}.",
+                   [Type, HookProviders]),
             case rebar_core:do(HookProviders, State1) of
                 {error, ProviderName} ->
                     ?DEBUG(format_error({bad_provider, Type, Command, ProviderName}), []),
@@ -55,11 +72,6 @@ run_provider_hooks_(Dir, Type, Command, Providers, TypeHooks, State) ->
             end
     end.
 
-format_error({bad_provider, Type, Command, {Name, Namespace}}) ->
-    io_lib:format("Unable to run ~ts hooks for '~p', command '~p' in namespace '~p' not found.", [Type, Command, Namespace, Name]);
-format_error({bad_provider, Type, Command, Name}) ->
-    io_lib:format("Unable to run ~ts hooks for '~p', command '~p' not found.", [Type, Command, Name]).
-
 run_hooks(Dir, pre, Command, Opts, State) ->
     run_hooks(Dir, pre_hooks, Command, Opts, State);
 run_hooks(Dir, post, Command, Opts, State) ->
@@ -67,17 +79,21 @@ run_hooks(Dir, post, Command, Opts, State) ->
 run_hooks(Dir, Type, Command, Opts, State) ->
     case rebar_opts:get(Opts, Type, []) of
         [] ->
-            ?DEBUG("run_hooks(~p, ~p, ~p) -> no hooks defined\n", [Dir, Type, Command]),
+            ?DEBUG("\t{~p, []}.", [Type]),
+            ?DIAGNOSTIC("run_hooks(~p, ~p, ~p) -> no hooks defined\n", [Dir, Type, Command]),
             ok;
         Hooks ->
             Env = rebar_env:create_env(State, Opts),
-            lists:foreach(fun({_, C, _}=Hook) when C =:= Command ->
-                                  apply_hook(Dir, Env, Hook);
-                             ({C, _}=Hook) when C =:= Command ->
-                                  apply_hook(Dir, Env, Hook);
-                             (_) ->
-                                  continue
-                          end, Hooks)
+            CommandHooks = lists:filter(
+                fun({_, C, _}) when C =:= Command -> true;
+                   ({C, _}) when C =:= Command -> true;
+                   (_) -> false
+                end,
+                Hooks
+            ),
+            ?DEBUG("\t{~p, ~p}.",
+                   [Type, CommandHooks]),
+            lists:foreach(fun(Hook) -> apply_hook(Dir, Env, Hook) end, CommandHooks)
     end.
 
 apply_hook(Dir, Env, {Arch, Command, Hook}) ->

src/rebar_prv_compile.erl

@@ -378,6 +378,7 @@ copy_app_dirs(AppInfo, OldAppDir, AppDir) ->
                 true ->
                     OutEbin = filename:join([AppDir, "ebin"]),
                     filelib:ensure_dir(filename:join([OutEbin, "dummy.beam"])),
+                    ?DEBUG("Copying existing files from ~ts to ~ts", [EbinDir, OutEbin]),
                     rebar_file_utils:cp_r(filelib:wildcard(filename:join([EbinDir, "*"])), OutEbin);
                 false ->
                     ok