Merge pull request #2393 from ferd/debug-expansion

Reworking more of the DEBUG output to be friendly

src/rebar_agent.erl

@@ -159,7 +159,7 @@ run(Namespace, Command, StrArgs, RState, Cwd) ->
         end
     catch
         ?WITH_STACKTRACE(Type, Reason, Stacktrace)
-            ?DEBUG("Agent Stacktrace: ~p", [Stacktrace]),
+            ?DIAGNOSTIC("Agent Stacktrace: ~p", [Stacktrace]),
             {{error, {Type, Reason}}, RState}
     end.
 
@@ -215,7 +215,7 @@ refresh_path(Path, Blacklist) ->
 
 refresh_path_do(Path, App) ->
     Modules = mods_in_path(Path),
-    ?DEBUG("reloading ~p from ~ts", [Modules, Path]),
+    ?DIAGNOSTIC("reloading ~p from ~ts", [Modules, Path]),
     code:replace_path(App, Path),
     reload_modules(Modules).
 
@@ -226,7 +226,7 @@ refresh_path_do(Path, App) ->
 %% run by no processes get unloaded by rebar_paths, without being loaded back in.
 refresh_path_blacklisted(Path) ->
     Modules = [M || M <- mods_in_path(Path), not is_loaded(M)],
-    ?DEBUG("ensure ~p loaded", [Modules]),
+    ?DIAGNOSTIC("ensure ~p loaded", [Modules]),
     code:add_pathz(Path), % in case the module is only in a new non-clashing path
      _ = [code:ensure_loaded(M) || M <- Modules],
     ok.
@@ -326,7 +326,7 @@ reload_modules(Modules, true) ->
                             reload_modules([ModError], false),
                             [ModError|Acc];
                         _ ->
-                            ?DEBUG("Module ~p failed to atomic load because ~p", [ModError, Error]),
+                            ?DIAGNOSTIC("Module ~p failed to atomic load because ~p", [ModError, Error]),
                             [ModError|Acc]
                     end
                 end,
@@ -342,7 +342,7 @@ reload_modules(Modules, false) ->
             case code:load_file(M) of
                 {module, M} -> ok;
                 {error, Error} ->
-                    ?DEBUG("Module ~p failed to load because ~p", [M, Error])
+                    ?DIAGNOSTIC("Module ~p failed to load because ~p", [M, Error])
             end
         end, Modules
     ).

src/rebar_compiler_dag.erl

@@ -296,12 +296,12 @@ maybe_rm_artifact_and_edge(G, OutDir, SrcExt, Ext, Source) ->
             case Targets of
                 [] ->
                     Target = target(OutDir, Source, SrcExt, Ext),
-                    ?DEBUG("Source ~ts is gone, deleting previous ~ts file if it exists ~ts", [Source, Ext, Target]),
+                    ?DIAGNOSTIC("Source ~ts is gone, deleting previous ~ts file if it exists ~ts", [Source, Ext, Target]),
                     file:delete(Target);
                 [_|_] ->
                     lists:foreach(fun(Target) ->
-                        ?DEBUG("Source ~ts is gone, deleting artifact ~ts "
-                                "if it exists", [Source, Target]),
+                        ?DIAGNOSTIC("Source ~ts is gone, deleting artifact ~ts "
+                                    "if it exists", [Source, Target]),
                         file:delete(Target)
                     end, Targets)
             end,

src/rebar_compiler_erl.erl

@@ -110,7 +110,7 @@ dependencies(Source, _SourceDir, Dirs, DepOpts) ->
           behaviour := Behaviours} ->
             %% TODO: check for core transforms?
             {_MissIncl, _MissInclLib} =/= {[],[]} andalso
-            ?DEBUG("Missing: ~p", [{_MissIncl, _MissInclLib}]),
+            ?DIAGNOSTIC("Missing: ~p", [{_MissIncl, _MissInclLib}]),
             lists:filtermap(
                 fun (Mod) -> rebar_compiler_epp:resolve_source(Mod, Dirs) end,
                 OptPTrans ++ PTrans ++ Behaviours) ++ AbsIncls
@@ -404,7 +404,7 @@ expand_file_names(Files, Dirs) ->
                       Res = rebar_utils:find_files_in_dirs(Dirs, [$^, Incl, $$], true),
                       case Res of
                           [] ->
-                              ?DEBUG("FILE ~p NOT FOUND", [Incl]),
+                              ?DIAGNOSTIC("FILE ~p NOT FOUND", [Incl]),
                               [];
                           _ ->
                               Res

src/rebar_fetch.erl

@@ -45,7 +45,7 @@ download_source(AppInfo, State)  ->
         throw:{no_resource, Type, Location} ->
             throw(?PRV_ERROR({no_resource, Location, Type}));
         ?WITH_STACKTRACE(C,T,S)
-            ?DEBUG("rebar_fetch exception ~p ~p ~p", [C, T, S]),
+            ?DIAGNOSTIC("rebar_fetch exception ~p ~p ~p", [C, T, S]),
             throw(?PRV_ERROR({fetch_fail, rebar_app_info:source(AppInfo)}))
     end.
 

src/rebar_parallel.erl

@@ -14,7 +14,7 @@ queue(Tasks, WorkF, WArgs, Handler, HArgs) ->
     Parent = self(),
     Worker = fun() -> worker(Parent, WorkF, WArgs) end,
     Jobs = min(length(Tasks), erlang:system_info(schedulers)),
-    ?DEBUG("Starting ~B worker(s)", [Jobs]),
+    ?DIAGNOSTIC("Starting ~B worker(s)", [Jobs]),
     Pids = [spawn_monitor(Worker) || _ <- lists:seq(1, Jobs)],
     parallel_dispatch(Tasks, Pids, Handler, HArgs).
 

src/rebar_paths.erl

@@ -14,6 +14,7 @@
 -spec set_paths(targets(), rebar_state:t()) -> ok.
 set_paths(UserTargets, State) ->
     Targets = normalize_targets(UserTargets),
+    ?DIAGNOSTIC("Setting paths to ~p", [Targets]),
     GroupPaths = path_groups(Targets, State),
     Paths = lists:append(lists:reverse([P || {_, P} <- GroupPaths])),
     code:add_pathsa(Paths),
@@ -24,6 +25,7 @@ set_paths(UserTargets, State) ->
 -spec unset_paths(targets(), rebar_state:t()) -> ok.
 unset_paths(UserTargets, State) ->
     Targets = normalize_targets(UserTargets),
+    ?DIAGNOSTIC("Removing ~p paths", [Targets]),
     GroupPaths = path_groups(Targets, State),
     Paths = lists:append([P || {_, P} <- GroupPaths]),
     [code:del_path(P) || P <- Paths],
@@ -240,4 +242,4 @@ get_runtime_apps([App|Rest0], AppsAcc0, AppsList) ->
                     error -> {Rest, Acc}
                 end
             end, {Rest0, sets:add_element(App, AppsAcc0)}, TotalApps),
-    get_runtime_apps(Rest1 ++ TotalApps, AppsAcc1, AppsList).
+    get_runtime_apps(Rest1 ++ TotalApps, AppsAcc1, AppsList).

src/rebar_prv_common_test.erl

@@ -90,7 +90,7 @@ run_tests(State, Opts) ->
     T = translate_paths(State, Opts),
     Opts1 = setup_logdir(State, T),
     Opts2 = turn_off_auto_compile(Opts1),
-    ?DEBUG("ct_opts ~p", [Opts2]),
+    ?DEBUG("Running tests with {ct_opts, ~p}.", [Opts2]),
     {RawOpts, _} = rebar_state:command_parsed_args(State),
     Result = case proplists:get_value(verbose, RawOpts, false) of
         true  -> run_test_verbose(Opts2);
@@ -120,7 +120,7 @@ format_error({error_reading_testspec, Reason}) ->
 %% Internal functions
 %% ===================================================================
 
-%% @doc Tries to make the symlink `_build/<profile>/logs/last` to the `ct_run` directory
+%% @doc Tries to make the symlink `_build/<profile>/logs/last' to the `ct_run' directory
 %% of the last common test run.
 -spec symlink_to_last_ct_logs(rebar_state:t(), list()) -> ok.
 symlink_to_last_ct_logs(State, Opts) ->
@@ -145,7 +145,7 @@ symlink_to_last_ct_logs(State, Opts) ->
                     %% and make a new updated one
                     rebar_file_utils:rm_rf(Target),
                     rebar_file_utils:symlink_or_copy(Existing, Target);
-                Reason -> ?DEBUG("Warning, couldn't make a symlink to ~ts, reason: ~p.", [Target, Reason])
+                Reason -> ?DIAGNOSTIC("Warning, couldn't make a symlink to ~ts, reason: ~p.", [Target, Reason])
             end
     end.
 
@@ -235,7 +235,7 @@ cfgopts(State) ->
 
 ensure_opts([], Acc) -> lists:reverse(Acc);
 ensure_opts([{cover, _}|Rest], Acc) ->
-    ?WARN("Cover specs not supported. See http://www.rebar3.org/docs/running-tests#common-test", []),
+    ?WARN("Cover specs not supported. See https://www.rebar3.org/docs/testing/ct/", []),
     ensure_opts(Rest, Acc);
 ensure_opts([{auto_compile, _}|Rest], Acc) ->
     ?WARN("Auto compile not supported", []),
@@ -389,6 +389,7 @@ compile(State, {ok, _} = Tests) ->
 compile(_State, Error) -> Error.
 
 do_compile(State) ->
+    ?DEBUG("Re-compiling the project under the test profile with CT options injected...", []),
     {ok, S} = rebar_prv_compile:do(State),
     ok = maybe_cover_compile(S),
     {ok, S}.
@@ -704,7 +705,7 @@ handle_keep_logs(LogDir, N) ->
                     SortedDirs = lists:reverse(lists:sort(Dirs)),
                     %% sort the log dirs and keep the N - 1 newest
                     {_Keep, Discard} = lists:split(N - 1, SortedDirs),
-                    ?DEBUG("Removing the following directories because keep_logs option was found: ~p", [Discard]),
+                    ?DEBUG("Removing the following directories because keep_logs is in ct_opts: ~p", [Discard]),
                     [rebar_file_utils:rm_rf(filename:join([LogDir, Dir])) || Dir <- Discard],
                     ok;
                 %% we still dont have enough log run directories as to crash

src/rebar_prv_cover.erl

@@ -326,6 +326,7 @@ cover_compile(State, Dirs) ->
     %% redirect cover output
     true = redirect_cover_output(State, CoverPid),
     ExclMods = rebar_state:get(State, cover_excl_mods, []),
+    ?DEBUG("Ignoring cover compilation of modules in {cover_excl_mods, ~p}", [ExclMods]),
     lists:foreach(fun(Dir) ->
         case file:list_dir(Dir) of
             {ok, Files} ->

src/rebar_prv_edoc.erl

@@ -48,6 +48,7 @@ do(State) ->
                     AppOpts = rebar_app_info:opts(AppInfo),
                     %% order of the merge is important to allow app opts overrides
                     AppEdocOpts = merge_opts(rebar_opts:get(AppOpts, edoc_opts, []), EdocOptsAcc),
+                    ?DEBUG("{edoc_opts, ~p}.", [AppEdocOpts]),
                     AppRes = (catch edoc:application(list_to_atom(AppName), AppDir, AppEdocOpts)),
                     rebar_hooks:run_all_hooks(Cwd, post, ?PROVIDER, Providers, AppInfo, State),
                     case {AppRes, ShouldAccPaths} of

src/rebar_prv_escriptize.erl

@@ -108,6 +108,7 @@ escriptize(State0, App) ->
     TopInclApps = lists:usort([ec_cnv:to_atom(AppName) | rebar_state:get(State, escript_incl_apps, [])]),
     AllApps = rebar_state:all_deps(State)++rebar_state:project_apps(State),
     InclApps = find_deps(TopInclApps, AllApps),
+    ?DEBUG("bundled applications:~n\t~p", [InclApps]),
     InclBeams = get_apps_beams(InclApps, AllApps),
 
     %% Look for a list of extra files to include in the output file.
@@ -130,6 +131,8 @@ escriptize(State0, App) ->
         , {comment, def("%%", State, escript_comment, "%%\n")}
         , {emu_args, def("%%!", State, escript_emu_args, DefaultEmuArgs)}
         , {archive, Files, []} ],
+    ?DEBUG("escript options:", []),
+    [?DEBUG("\t{escript_~p, ~p}.", [K, V]) || {K, V} <- lists:droplast(EscriptSections)],
     case escript:create(Filename, EscriptSections) of
         ok -> ok;
         {error, EscriptError} ->
@@ -249,7 +252,7 @@ find_deps(AppNames, AllApps) ->
 %% Should look at the app files to find direct dependencies
 find_deps_of_deps([], _, Acc) -> Acc;
 find_deps_of_deps([Name|Names], Apps, Acc) ->
-    ?DEBUG("processing ~p", [Name]),
+    ?DIAGNOSTIC("processing ~p", [Name]),
     {ok, App} = rebar_app_utils:find(Name, Apps),
     DepNames = proplists:get_value(applications, rebar_app_info:app_details(App), []),
     BinDepNames = [rebar_utils:to_binary(Dep) || Dep <- DepNames,
@@ -258,7 +261,7 @@ find_deps_of_deps([Name|Names], Apps, Acc) ->
                    DepDir =:= {error, bad_name} orelse % those are all local
                    not lists:prefix(code:root_dir(), DepDir)]
                 -- ([Name|Names]++Acc), % avoid already seen deps
-    ?DEBUG("new deps of ~p found to be ~p", [Name, BinDepNames]),
+    ?DIAGNOSTIC("new deps of ~p found to be ~p", [Name, BinDepNames]),
     find_deps_of_deps(BinDepNames ++ Names, Apps, BinDepNames ++ Acc).
 
 def(Rm, State, Key, Default) ->

src/rebar_prv_eunit.erl

@@ -81,8 +81,8 @@ do(State, Tests) ->
 run_tests(State, Tests) ->
     T = translate_paths(State, Tests),
     EUnitOpts = resolve_eunit_opts(State),
-    ?DEBUG("eunit_tests ~p", [T]),
-    ?DEBUG("eunit_opts  ~p", [EUnitOpts]),
+    ?DEBUG("finding tests in:~n\t{eunit_tests, ~p}.", [T]),
+    ?DEBUG("with options:~n\t{eunit_opts, ~p}.", [EUnitOpts]),
     try eunit:test(T, EUnitOpts) of
       Result ->
         ok = maybe_write_coverdata(State),

src/rebar_prv_help.erl

@@ -55,14 +55,15 @@ format_error(Reason) ->
 %% print help/usage string
 %%
 help(State) ->
-    ?CONSOLE("Rebar3 is a tool for working with Erlang projects.~n~n", []),
+    ?CONSOLE("Rebar3 is a tool for working with Erlang projects.~n", []),
     OptSpecList = rebar3:global_option_spec_list(),
     getopt:usage(OptSpecList, "rebar3", "", []),
-    ?CONSOLE("~nSeveral tasks are available:~n", []),
+    ?CONSOLE("  Set the environment variable DEBUG=1 for detailed output.~n", []),
+    ?CONSOLE("Several tasks are available:~n", []),
 
     providers:help(rebar_state:providers(State)),
 
-    ?CONSOLE("~nRun 'rebar3 help <TASK>' for details.~n~n", []).
+    ?CONSOLE("~nRun 'rebar3 help <TASK>' for details.", []).
 
 task_help(Namespace, Name, State) ->
     Providers = rebar_state:providers(State),