concuerror

%%% @private
%%% @doc
%%% The logger is a process responsible for collecting information and
%%% sending output to the user in reports and stderr.

-module(concuerror_logger).

-export([start/1, complete/2, plan/1, log/5, race/3, stop/2, print/3, time/2]).
-export([bound_reached/1, set_verbosity/2]).
-export([graph_set_node/3, graph_new_node/4, graph_race/3]).
-export([print_log_message/3]).
-export([showing_progress/1, progress_help/0]).

-export_type([logger/0, log_level/0]).

%%------------------------------------------------------------------------------

-include("concuerror.hrl").

-type logger() :: pid().
-type log_level() :: 0..7.

-define(TICKER_TIMEOUT, 500).
-define(llog(L, F, A), ?log(self(), L, F, A)).
-define(llog(L, F), ?llog(L, F, [])).

%%------------------------------------------------------------------------------

-type unique_id() :: concuerror_scheduler:unique_id().

-type stream() :: 'standard_io' | 'standard_error' | 'race' | file:filename().
-type graph_data() ::
        { file:io_device()
        , unique_id() | 'init'
        , unique_id() | 'none'
        }.

%%------------------------------------------------------------------------------

-type unique_ids() :: sets:set(integer()).

%%------------------------------------------------------------------------------

-type timestamp() :: integer().
timestamp() ->
  erlang:monotonic_time(milli_seconds).
timediff(After, Before) ->
  (After - Before) / 1000.

%%------------------------------------------------------------------------------

-record(rate_info, {
          average   :: 'init' | concuerror_window_average:average(),
          prev      :: non_neg_integer(),
          timestamp :: timestamp()
         }).

-record(logger_state, {
          already_emitted = sets:new() :: unique_ids(),
          bound_reached = false        :: boolean(),
          emit_logger_tips = initial   :: 'initial' | 'false',
          errors = 0                   :: non_neg_integer(),
          estimator                    :: concuerror_estimator:estimator(),
          graph_data                   :: graph_data() | 'disable',
          interleaving_bound           :: concuerror_options:bound(),
          last_had_output = false      :: boolean(),
          log_all                      :: boolean(),
          log_msgs = []                :: [string()],
          output                       :: file:io_device() | 'disable',
          output_name                  :: string(),
          print_depth                  :: pos_integer(),
          rate_info = init_rate_info() :: #rate_info{},
          streams = []                 :: [{stream(), [string()]}],
          timestamp = timestamp()      :: timestamp(),
          ticker = none                :: pid() | 'none',
          ticks = 0                    :: non_neg_integer(),
          traces_explored = 0          :: non_neg_integer(),
          traces_ssb = 0               :: non_neg_integer(),
          traces_total = 0             :: non_neg_integer(),
          verbosity                    :: log_level()
         }).

%%------------------------------------------------------------------------------

-spec start(concuerror_options:options()) -> pid().

start(Options) ->
  Parent = self(),
  Ref = make_ref(),
  Fun =
    fun() ->
        State = initialize(Options),
        Parent ! Ref,
        loop(State)
    end,
  P = spawn_link(Fun),
  receive
    Ref -> P
  end.

initialize(Options) ->
  Timestamp = format_utc_timestamp(),
  Graph = ?opt(graph, Options),
  {Output, OutputName} = ?opt(output, Options),
  LogAll = ?opt(log_all, Options),
  Processes = ?opt(processes, Options),
  SymbolicNames = ?opt(symbolic_names, Options),
  Verbosity = ?opt(verbosity, Options),

  GraphData = graph_preamble(Graph),
  Header =
    io_lib:format("~s started at ~s~n", [concuerror:version(), Timestamp]),
  Ticker =
    case showing_progress(Verbosity) of
      false -> none;
      true ->
        to_stderr("~s~n", [Header]),
        initialize_ticker(),
        ?llog(?linfo, "Showing progress ('-h progress', for details)~n"),
        Self = self(),
        spawn_link(fun() -> ticker(Self) end)
    end,
  case Output =:= disable of
    true ->
      ?llog(?lwarning, "No output report will be generated~n");
    false ->
      ?llog(?linfo, "Writing results in ~s~n", [OutputName])
  end,
  case GraphData =:= disable of
    true ->
      ok;
    false ->
      {_, GraphName} = Graph,
      ?llog(?linfo, "Writing graph in ~s~n", [GraphName])
  end,
  case LogAll of
    true ->
      ?llog(?lwarning, "Logging all interleavings ('--log_all true')~n");
    false ->
      ?llog(?linfo, "Only logging errors ('--log_all false')~n")
  end,
  PrintableOptions =
    delete_props(
      [estimator, graph, output, processes, timers, verbosity],
      Options),
  to_file(Output, "~s", [Header]),
  to_file(
    Output,
    " Options:~n"
    "  ~p~n",
    [lists:sort(PrintableOptions)]),
  ?autoload_and_log(io_lib, self()),
  ok = setup_symbolic_names(SymbolicNames, Processes),
  #logger_state{
     estimator = ?opt(estimator, Options),
     graph_data = GraphData,
     interleaving_bound = ?opt(interleaving_bound, Options),
     log_all = LogAll,
     output = Output,
     output_name = OutputName,
     print_depth = ?opt(print_depth, Options),
     ticker = Ticker,
     verbosity = Verbosity
    }.

delete_props([], Proplist) ->
  Proplist;
delete_props([Key|Rest], Proplist) ->
  delete_props(Rest, proplists:delete(Key, Proplist)).

-spec bound_reached(logger()) -> ok.

bound_reached(Logger) ->
  Logger ! bound_reached,
  ok.

-spec plan(logger()) -> ok.

plan(Logger) ->
  Logger ! plan,
  ok.

-spec complete(logger(), concuerror_scheduler:interleaving_result()) -> ok.

complete(Logger, Warnings) ->
  Ref = make_ref(),
  Logger ! {complete, Warnings, self(), Ref},
  receive
    Ref -> ok
  end.

-spec log(logger(), log_level(), term(), string(), [term()]) -> ok.

log(Logger, Level, Tag, Format, Data) ->
  Logger ! {log, Level, Tag, Format, Data},
  ok.

-spec stop(logger(), term()) -> concuerror:analysis_result().

stop(Logger, Status) ->
  Logger ! {stop, Status, self()},
  receive
    {stopped, ExitStatus} -> ExitStatus
  end.

-spec print(logger(), stream(), string()) -> ok.

print(Logger, Type, String) ->
  Logger ! {print, Type, String},
  ok.

-spec time(logger(), term()) -> ok.

time(Logger, Tag) ->
  Logger ! {time, Tag},
  ok.

-spec race(logger(), {index(), event()}, {index(), event()}) -> ok.

race(Logger, EarlyEvent, Event) ->
  Logger ! {race, EarlyEvent, Event},
  ok.

-spec set_verbosity(logger(), log_level()) -> ok.

set_verbosity(Logger, Verbosity) ->
  Logger ! {set_verbosity, Verbosity},
  ok.

-spec print_log_message(log_level(), string(), [term()]) -> ok.

print_log_message(Level, Format, Args) ->
  LevelFormat = level_to_tag(Level),
  NewFormat = "* " ++ LevelFormat ++ Format,
  to_stderr(NewFormat, Args).

-spec showing_progress(log_level()) -> boolean().

showing_progress(Verbosity) ->
  (Verbosity =/= ?lquiet) andalso (Verbosity < ?ltiming).

%%------------------------------------------------------------------------------

loop(State) ->
  Message =
    receive
      {stop, _, _} = Stop ->
        receive
          M -> self() ! Stop, M
        after
          0 -> Stop
        end;
      M -> M
    end,
  loop(Message, State).

loop(Message,
     #logger_state{
        emit_logger_tips = initial,
        errors = Errors,
        traces_explored = 10,
        traces_total = TracesTotal
       } = State) ->
  case TracesTotal > 250 of
    true ->
      ManyMsg =
        "A lot of events in this test are racing. You can see such pairs"
        " by using '--show_races' true. You may want to consider reducing some"
        " parameters in your test (e.g. number of processes or events).~n",
      ?llog(?ltip, ManyMsg);
    false -> ok
  end,
  case Errors =:= 10 of
    true ->
      ErrorsMsg =
        "Each of the first 10 interleavings explored so far had some error."
        " This can make later debugging difficult, as the generated report will"
        " include too much info. Consider refactoring your code, or using the"
        " appropriate options to filter out irrelevant errors.~n",
      ?llog(?ltip, ErrorsMsg);
    false -> ok
  end,
  loop(Message, State#logger_state{emit_logger_tips = false});

loop(Message, State) ->
  #logger_state{
     already_emitted = AlreadyEmitted,
     errors = Errors,
     last_had_output = LastHadOutput,
     log_all = LogAll,
     log_msgs = LogMsgs,
     output = Output,
     output_name = OutputName,
     print_depth = PrintDepth,
     streams = Streams,
     timestamp = Timestamp,
     traces_explored = TracesExplored,
     traces_ssb = TracesSSB,
     traces_total = TracesTotal,
     verbosity = Verbosity
    } = State,
  case Message of
    {time, Tag} ->
      Now = timestamp(),
      Diff = timediff(Now, Timestamp),
      Msg = "~nTimer: +~6.3fs ~s~n",
      loop(
        {log, ?ltiming, none, Msg, [Diff, Tag]},
        State#logger_state{timestamp = Now});
    {race, EarlyEvent, Event} ->
      print_depth_tip(),
      Msg =
        io_lib:format(
          "~n* ~s~n  ~s~n",
          [concuerror_io_lib:pretty_s(E, PrintDepth)
           || E <- [EarlyEvent, Event]]),
      loop({print, race, Msg}, State);
    {log, Level, Tag, Format, Data} ->
      {NewLogMsgs, NewAlreadyEmitted} =
        case Tag =/= ?nonunique andalso sets:is_element(Tag, AlreadyEmitted) of
          true -> {LogMsgs, AlreadyEmitted};
          false ->
            case Verbosity < Level of
              true  -> ok;
              false ->
                LevelFormat = level_to_tag(Level),
                NewFormat = "* " ++ LevelFormat ++ Format,
                printout(State, NewFormat, Data)
            end,
            NLM =
              case Level < ?ltiming of
                true  -> orddict:append(Level, {Format, Data}, LogMsgs);
                false -> LogMsgs
              end,
            NAE =
              case Tag =/= ?nonunique of
                true -> sets:add_element(Tag, AlreadyEmitted);
                false -> AlreadyEmitted
              end,
            {NLM, NAE}
        end,
      loop(State#logger_state{
             already_emitted = NewAlreadyEmitted,
             log_msgs = NewLogMsgs});
    {graph, Command} ->
      loop(graph_command(Command, State));
    {stop, SchedulerStatus, Scheduler} ->
      NewState = stop_ticker(State),
      separator(Output, $#),
      to_file(Output, "Exploration completed!~n", []),
      ExitStatus =
        case SchedulerStatus =:= normal of
          true ->
            case Errors =/= 0 of
              true ->
                case Verbosity =:= ?lquiet of
                  true -> ok;
                  false ->
                    Form = "Errors were found! (check ~s)~n",
                    printout(NewState, Form, [OutputName])
                end,
                error;
              false ->
                to_file(Output, "  No errors found!~n", []),
                ok
            end;
          false -> fail
        end,
      separator(Output, $#),
      print_log_msgs(Output, LogMsgs),
      FinishTimestamp = format_utc_timestamp(),
      Format = "Done at ~s (Exit status: ~p)~n  Summary: ",
      Args = [FinishTimestamp, ExitStatus],
      to_file(Output, Format, Args),
      IntMsg = final_interleavings_message(NewState),
      to_file(Output, "~s", [IntMsg]),
      ok = close_files(NewState),
      case Verbosity =:= ?lquiet of
        true -> ok;
        false ->
          FinalFormat = Format ++ IntMsg,
          printout(NewState, FinalFormat, Args)
      end,
      Scheduler ! {stopped, ExitStatus},
      ok;
    plan ->
      NewState = State#logger_state{traces_total = TracesTotal + 1},
      loop(NewState);
    bound_reached ->
      NewState = State#logger_state{bound_reached = true},
      loop(NewState);
    {print, Type, String} ->
      NewStreams = orddict:append(Type, String, Streams),
      NewState = State#logger_state{streams = NewStreams},
      loop(NewState);
    {set_verbosity, NewVerbosity} ->
      NewState = State#logger_state{verbosity = NewVerbosity},
      loop(NewState);
    {complete, {Warnings, TraceInfo}, Scheduler, Ref} ->
      %% We may have race information referring to the previous
      %% interleaving, as race analysis happens after trace logging.
      RaceInfo = [S || S = {T, _} <- Streams, T =:= race],
      case RaceInfo =:= [] of
        true -> ok;
        false ->
          case LastHadOutput of
            true -> ok;
            false ->
              %% Add missing header
              separator(Output, $#),
              to_file(Output, "Interleaving #~p~n", [TracesExplored])
          end,
          separator(Output, $-),
          print_streams(RaceInfo, Output)
      end,
      case TraceInfo =/= [] of
        true ->
          separator(Output, $#),
          to_file(Output, "Interleaving #~p~n", [TracesExplored + 1]),
          separator(Output, $-),
          case Warnings =:= [] of
            true ->
              to_file(Output, "No errors found.~n", []),
              separator(Output, $-);
            false ->
              to_file(Output, "Errors found:~n", []),
              print_depth_tip(),
              WarnStr =
                [concuerror_io_lib:error_s(W, PrintDepth) || W <- Warnings],
              to_file(Output, "~s", [WarnStr]),
              separator(Output, $-)
          end,
          print_streams([S || S = {T, _} <- Streams, T =/= race], Output),
          to_file(Output, "Event trace:~n", []),
          concuerror_io_lib:pretty(Output, TraceInfo, PrintDepth);
        false -> ok
      end,
      {NewErrors, NewSSB, GraphFinal, GraphColor} =
        case Warnings of
          sleep_set_block ->
            Msg =
              "Some interleavings were 'sleep-set blocked' (SSB). This"
              " is expected, since you are not using '--dpor"
              " optimal', but indicates wasted effort.~n",
            ?unique(self(), ?lwarning, Msg, []),
            {Errors, TracesSSB + 1, "SSB", "yellow"};
          [] ->
            {Errors, TracesSSB, "Ok", "limegreen"};
          _ ->
            ErrorString =
              case proplists:get_value(fatal, Warnings) of
                true -> " (Concuerror crashed)";
                undefined ->
                  case proplists:get_value(deadlock, Warnings) of
                    undefined -> "";
                    Deadlocks ->
                      Pids = [element(1, D) || D <- Deadlocks],
                      io_lib:format(" (~p blocked)", [Pids])
                  end
              end,
            {Errors + 1, TracesSSB, "Error" ++ ErrorString, "red"}
        end,
      _ =
        graph_command({status, TracesExplored, GraphFinal, GraphColor}, State),
      NewState =
        State#logger_state{
          last_had_output = LogAll orelse NewErrors =/= Errors,
          streams = [],
          traces_explored = TracesExplored + 1,
          traces_ssb = NewSSB,
          errors = NewErrors
         },
      Scheduler ! Ref,
      loop(NewState);
    tick ->
      N = clear_ticks(1),
      loop(progress_refresh(N, State))
  end.

format_utc_timestamp() ->
  TS = os:timestamp(),
  {{Year, Month, Day}, {Hour, Minute, Second}} =
    calendar:now_to_local_time(TS),
  Mstr =
    element(Month, {"Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug",
                    "Sep", "Oct", "Nov", "Dec"}),
  io_lib:format("~2..0w ~s ~4w ~2..0w:~2..0w:~2..0w",
                [Day, Mstr, Year, Hour, Minute, Second]).

printout(#logger_state{ticker = Ticker} = State, Format, Data)
  when Ticker =/= none ->
  progress_clear(),
  to_stderr(Format, Data),
  progress_print(State);
printout(_, Format, Data) ->
  to_stderr(Format, Data).

print_log_msgs(Output, LogMsgs) ->
  ForeachInner =
    fun({Format, Data}) ->
        to_file(Output, "* " ++ Format, Data)
    end,
  Foreach =
    fun({Type, Messages}) ->
        Header = level_to_string(Type),
        Suffix =
          case Type of
            ?linfo    -> "";
            _         -> "s"
          end,
        to_file(Output, "~s~s:~n", [Header, Suffix]),
        separator(Output, $-),
        lists:foreach(ForeachInner, Messages),
        to_file(Output, "~n", []),
        separator(Output, $#)
    end,
  lists:foreach(Foreach, LogMsgs).

level_to_tag(Level) ->
  Suffix =
    case Level > ?linfo of
      true -> "";
      false -> ": "
    end,
  level_to_string(Level) ++ Suffix.

level_to_string(Level) ->
  case Level of
    ?lerror   -> "Error";
    ?lwarning -> "Warning";
    ?ltip     -> "Tip";
    ?linfo    -> "Info";
    _ -> ""
  end.

%%------------------------------------------------------------------------------

initialize_ticker() ->
  self() ! tick,
  progress_initial_padding().

ticker(Logger) ->
  Logger ! tick,
  receive
    {stop, L} -> L ! stopped
  after
    ?TICKER_TIMEOUT -> ticker(Logger)
  end.

clear_ticks(N) ->
  receive
    tick -> clear_ticks(N + 1)
  after
    0 -> N
  end.

stop_ticker(#logger_state{ticker = Ticker} = State) ->
  case is_pid(Ticker) of
    true ->
      Ticker ! {stop, self()},
      progress_clear(),
      receive
        stopped -> State#logger_state{ticker = none}
      end;
    false -> State
  end.

%%------------------------------------------------------------------------------

separator_string(Char) ->
  lists:duplicate(80, Char).

separator(Output, Char) ->
  to_file(Output, "~s~n", [separator_string(Char)]).

print_streams(Streams, Output) ->
  Fold =
    fun(Tag, Buffer, ok) ->
        print_stream(Tag, Buffer, Output),
        ok
    end,
  orddict:fold(Fold, ok, Streams).

print_stream(Tag, Buffer, Output) ->
  to_file(Output, stream_tag_to_string(Tag), []),
  to_file(Output, "~s~n", [Buffer]),
  case Tag =/= race of
    true ->
      to_file(Output, "~n", []),
      separator(Output, $-);
    false -> ok
  end.

stream_tag_to_string(standard_io) -> "Standard Output:~n";
stream_tag_to_string(standard_error) -> "Standard Error:~n";
stream_tag_to_string(race) -> "New races found:". % ~n is added by buffer

%%------------------------------------------------------------------------------

progress_initial_padding() ->
  Line = progress_line(0),
  to_stderr("~s~n", [Line]),
  to_stderr("~s~n", [progress_header(0)]),
  to_stderr("~s~n", [Line]),
  to_stderr("~n", []).

progress_clear() ->
  delete_lines(4).

progress_refresh(N, #logger_state{ticks = T} = State) ->
  %% No extra line afterwards to ease printing of 'running logs'.
  delete_lines(1),
  {Str, NewState} = progress_content(State#logger_state{ticks = T + N}),
  to_stderr("~s~n", [Str]),
  NewState.

delete_lines(0) -> ok;
delete_lines(N) ->
  to_stderr("~c[1A~c[2K\r", [27, 27]),
  delete_lines(N - 1).

progress_print(#logger_state{traces_ssb = SSB} = State) ->
  Line = progress_line(SSB),
  to_stderr("~s~n", [Line]),
  to_stderr("~s~n", [progress_header(SSB)]),
  to_stderr("~s~n", [Line]),
  {Str, _NewState} = progress_content(State),
  to_stderr("~s~n", [Str]).

-spec progress_help() -> string().

progress_help() ->
  io_lib:format(
    "Errors      : Schedulings with errors~n"
    "Explored    : Schedulings already explored~n"
    "SSB (if >0) : Sleep set blocked schedulings (wasted effort)~n"
    "Planned     : Schedulings that will certainly be explored~n"
    "~~Rate       : Average rate of exploration (in schedulings/s)~n"
    "Elapsed     : Time elapsed (actively running)~n"
    "Est.Total   : Estimation of total number of schedulings (see below)~n"
    "Est.TTC     : Estimated time to completion (see below)~n"
    "~n"
    "Estimations:~n"
    "The total number of schedulings is estimated from the shape of the"
    " exploration tree. It has been observed to be WITHIN ONE ORDER OF"
    " MAGNITUDE of the actual number, when using default options.~n"
    "The time to completion is estimated using the estimated remaining"
    " schedulings (Est.Total - Explored) divided by the current Rate.~n"
    , []).

progress_header(0) ->
  progress_header_common("");
progress_header(_State) ->
  progress_header_common("     SSB |").

progress_header_common(SSB) ->
  ""
    "Errors |"
    "   Explored |"
    ++ SSB ++
    " Planned |"
    " ~Rate |"
    " Elapsed |"
    " Est.Total |"
    " Est.TTC".

progress_line(SSB) ->
  L = lists:duplicate(length(progress_header(SSB)), $-),
  io_lib:format("~s", [L]).

progress_content(State) ->
  #logger_state{
     errors = Errors,
     estimator = Estimator,
     rate_info = RateInfo,
     ticks = Ticks,
     traces_explored = TracesExplored,
     traces_ssb = TracesSSB,
     traces_total = TracesTotal
    } = State,
  Planned = TracesTotal - TracesExplored,
  {Rate, NewRateInfo} = update_rate(RateInfo, TracesExplored),
  Estimation = concuerror_estimator:get_estimation(Estimator),
  EstimatedTotal = sanitize_estimation(Estimation, TracesTotal),
  ErrorsStr =
    case Errors of
      0 -> "none";
      _ when Errors < 10000 -> add_seps_to_int(Errors);
      _ -> "> 10k"
    end,
  [TracesExploredStr, PlannedStr] =
    [add_seps_to_int(S) || S <- [TracesExplored, Planned]],
  SSBStr =
    case TracesSSB of
      0 -> "";
      _ when TracesSSB < 100000 ->
        io_lib:format("~8s |", [add_seps_to_int(TracesSSB)]);
      _ -> io_lib:format("~8s |", ["> 100k"])
    end,
  RateStr =
    case Rate of
      init -> "...";
      0    -> "<1/s";
      _    -> io_lib:format("~w/s", [Rate])
    end,
  EstimatedTotalStr =
    case EstimatedTotal of
      unknown -> "...";
      _ when EstimatedTotal < 10000000 -> add_seps_to_int(EstimatedTotal);
      _ ->
        Low = trunc(math:log10(EstimatedTotal)),
        io_lib:format("< 10e~w", [Low + 1])
    end,
  ElapsedStr = time_string(round(Ticks * ?TICKER_TIMEOUT / 1000)),
  CompletionStr = estimate_completion(EstimatedTotal, TracesExplored, Rate),
  Str =
    io_lib:format(
      "~6s |"
      "~11s |"
      "~s"
      "~8s |"
      "~6s |"
      "~8s |"
      "~10s |"
      "~8s",
      [ErrorsStr, TracesExploredStr, SSBStr, PlannedStr,
       RateStr, ElapsedStr, EstimatedTotalStr, CompletionStr]
     ),
  NewState = State#logger_state{rate_info = NewRateInfo},
  {Str, NewState}.

%%------------------------------------------------------------------------------

init_rate_info() ->
  #rate_info{
     average   = init,
     prev      = 0,
     timestamp = timestamp()
    }.

update_rate(RateInfo, TracesExplored) ->
  #rate_info{
     average   = Average,
     prev      = Prev,
     timestamp = Old
    } = RateInfo,
  New = timestamp(),
  {Rate, NewAverage} =
    case TracesExplored < 10 of
      true ->
        {init, init};
      false ->
        Time = timediff(New, Old),
        Diff = TracesExplored - Prev,
        CurrentRate = Diff / (Time + 0.0001),
        case Average =:= init of
          true ->
            NA = concuerror_window_average:init(CurrentRate, 50),
            {round(CurrentRate), NA};
          false ->
            {R, NA} =
              concuerror_window_average:update(CurrentRate, Average),
            {round(R), NA}
        end
    end,
  NewRateInfo =
    RateInfo#rate_info{
      average   = NewAverage,
      prev      = TracesExplored,
      timestamp = New
     },
  {Rate, NewRateInfo}.

sanitize_estimation(Estimation, _)
  when not is_number(Estimation) -> Estimation;
sanitize_estimation(Estimation, TracesTotal) ->
  EstSignificant = two_significant(Estimation),
  case EstSignificant > TracesTotal of
    true -> EstSignificant;
    false -> two_significant(TracesTotal)
  end.

two_significant(Number) when Number < 100 -> Number + 1;
two_significant(Number) -> 10 * two_significant(Number div 10).

%%------------------------------------------------------------------------------

to_stderr(Format, Data) ->
  to_file(standard_error, Format, Data).

to_file(disable, _, _) ->
  ok;
to_file(Output, Format, Data) ->
  Msg = io_lib:format(Format, Data),
  io:format(Output, "~s", [Msg]).

%%------------------------------------------------------------------------------

final_interleavings_message(State) ->
  #logger_state{
     bound_reached = BoundReached,
     errors = Errors,
     interleaving_bound = InterleavingBound,
     traces_explored = TracesExplored,
     traces_ssb = TracesSSB,
     traces_total = TracesTotal
    } = State,
  SSB =
    case TracesSSB =:= 0 of
      true -> "";
      false -> io_lib:format(" (~p sleep-set blocked)", [TracesSSB])
    end,
  BR =
    case BoundReached of
      true -> " (the scheduling bound was reached)";
      false -> ""
    end,
  ExploreTotal = min(TracesTotal, InterleavingBound),
  io_lib:format("~p errors, ~p/~p interleavings explored~s~s~n",
                [Errors, TracesExplored, ExploreTotal, SSB, BR]).

%%------------------------------------------------------------------------------

estimate_completion(Estimated, Explored, Rate)
  when not is_number(Estimated);
       not is_number(Explored);
       not is_number(Rate) ->
  "...";
estimate_completion(Estimated, Explored, Rate) ->
  Remaining = Estimated - Explored,
  Completion = round(Remaining/(Rate + 0.001)),
  approximate_time_string(Completion).

%%------------------------------------------------------------------------------

-type posint() :: pos_integer().
-type split_fun() :: fun((posint()) -> posint() | {posint(), posint()}).

-record(time_formatter, {
          threshold  = 1       :: pos_integer() | 'infinity',
          rounding   = 1       :: pos_integer(),
          split_fun            :: split_fun(),
          one_format = "~w"    :: string(),
          two_format = "~w ~w" :: string()
         }).

approximate_time_string(Seconds) ->
  lists:flatten(time_string(approximate_time_formatters(), Seconds)).

time_string(Seconds) ->
  lists:flatten(time_string(time_formatters(), Seconds)).

time_string([ATF|Rest], Value) ->
  #time_formatter{
     threshold  = Threshold,
     rounding   = Rounding,
     split_fun  = SplitFun,
     one_format = OneFormat,
     two_format = TwoFormat
    } = ATF,
  case Value >= Threshold of
    true -> time_string(Rest, Value div Rounding);
    false ->
      case SplitFun(Value) of
        {High, Low} -> io_lib:format(TwoFormat, [High, Low]);
        Single -> io_lib:format(OneFormat, [Single])
      end
  end.

time_formatters() ->
  SecondsSplitFun = fun(S) -> S end,
  SecondsATF =
    #time_formatter{
       threshold  = 60 * 1,
       rounding   = 1,
       split_fun  = SecondsSplitFun,
       one_format = "~ws"
      },
  MinutesSplitFun =
    fun(Seconds) -> {Seconds div 60, Seconds rem 60} end,
  MinutesATF =
    #time_formatter{
       threshold  = 60 * 60,
       rounding   = 60,
       split_fun  = MinutesSplitFun,
       two_format = "~wm~2..0ws"
      },
  HoursSplitFun =
    fun(Minutes) -> {Minutes div 60, Minutes rem 60} end,
  HoursATF =
    #time_formatter{
       threshold  = 2 * 24 * 60,
       rounding   = 60,
       split_fun  = HoursSplitFun,
       two_format = "~wh~2..0wm"
      },
  DaysSplitFun =
    fun(Hours) -> {Hours div 24, Hours rem 24} end,
  DaysATF =
    #time_formatter{
       threshold  = infinity,
       split_fun  = DaysSplitFun,
       two_format = "~wd~2..0wh"
      },
  [ SecondsATF
  , MinutesATF
  , HoursATF
  , DaysATF
  ].

approximate_time_formatters() ->
  SecondsSplitFun = fun(_) -> 1 end,
  SecondsATF =
    #time_formatter{
       threshold  = 60 * 1,
       rounding   = 60,
       split_fun  = SecondsSplitFun,
       one_format = "<~wm"
      },
  MinutesSplitFun = fun(Minutes) -> Minutes end,
  MinutesATF =
    #time_formatter{
       threshold  = 30 * 1,
       rounding   = 10,
       split_fun  = MinutesSplitFun,
       one_format = "~wm"
      },
  TensSplitFun =
    fun(Tens) ->
        case Tens < 6 of
          true -> Tens * 10;
          false -> {Tens div 6, (Tens rem 6) * 10}
        end
    end,
  TensATF =
    #time_formatter{
       threshold  = 2 * 6,
       rounding   = 6,
       split_fun  = TensSplitFun,
       one_format = "~wm",
       two_format = "~wh~2..0wm"
      },
  HoursSplitFun =
    fun(Hours) ->
        case Hours < 60 of
          true -> Hours;
          false -> {Hours div 24, Hours rem 24}
        end
    end,
  HoursATF =
    #time_formatter{
       threshold  = 2 * 24,
       rounding   = 24,
       split_fun  = HoursSplitFun,
       one_format = "~wh",
       two_format = "~wd~2..0wh"
      },
  DaysSplitFun = fun(Days) -> Days end,
  DaysATF =
    #time_formatter{
       threshold  = 12 * 30,
       rounding   = 30,
       split_fun  = DaysSplitFun,
       one_format = "~wd"
      },
  MonthsSplitFun =
    fun(Months) -> {Months div 12, Months rem 12} end,
  MonthsATF =
    #time_formatter{
       threshold  = 50 * 12,
       rounding   = 12,
       split_fun  = MonthsSplitFun,
       two_format = "~wy~2..0wm"
      },
  YearsSplitFun =
    fun(Years) -> Years end,
  YearsATF =
    #time_formatter{
       threshold  = 10000,
       rounding = 1,
       split_fun  = YearsSplitFun,
       one_format = "~wy"
      },
  TooMuchSplitFun =
    fun(_) -> 10000 end,
  TooMuchATF =
    #time_formatter{
       threshold  = infinity,
       split_fun  = TooMuchSplitFun,
       one_format = "> ~wy"
      },
  [ SecondsATF
  , MinutesATF
  , TensATF
  , HoursATF
  , DaysATF
  , MonthsATF
  , YearsATF
  , TooMuchATF
  ].

%%------------------------------------------------------------------------------

add_seps_to_int(Integer) when Integer < 1000 -> integer_to_list(Integer);
add_seps_to_int(Integer) ->
  Rem = Integer rem 1000,
  DivS = add_seps_to_int(Integer div 1000),
  io_lib:format("~s ~3..0w", [DivS, Rem]).

%%------------------------------------------------------------------------------

-spec graph_set_node(logger(), unique_id(), unique_id()) -> ok.

graph_set_node(Logger, Parent, Sibling) ->
  Logger ! {graph, {set_node, Parent, Sibling}},
  ok.

-spec graph_new_node(logger(), unique_id(), index(), event()) -> ok.

graph_new_node(Logger, Ref, Index, Event) ->
  Logger ! {graph, {new_node, Ref, Index, Event}},
  ok.

-spec graph_race(logger(), unique_id(), unique_id()) -> ok.
graph_race(Logger, EarlyRef, Ref) ->
  Logger ! {graph, {race, EarlyRef, Ref}},
  ok.

graph_preamble({disable, ""}) -> disable;
graph_preamble({GraphFile, _}) ->
  to_file(
    GraphFile,
    "digraph {~n"
    "  graph [ranksep=0.3]~n"
    "  node [shape=box,width=7,fontname=Monospace]~n"
    "  \"init\" [label=\"Initial\"];~n"
    "  subgraph interleaving_1 {~n", []),
  {GraphFile, init, none}.

graph_command(_Command, #logger_state{graph_data = disable} = State) -> State;
graph_command(Command, State) ->
  #logger_state{
     graph_data = {GraphFile, Parent, Sibling} = Graph,
     print_depth = PrintDepth
    } = State,
  NewGraph =
    case Command of
      {new_node, Ref, I, Event} ->
        ErrorS =
          case Event#event.event_info of
            #exit_event{reason = normal} ->
              ",color=limegreen,penwidth=5";
            #exit_event{} ->
              ",color=red,penwidth=5";
            #builtin_event{status = {crashed, _}} ->
              ",color=orange,penwidth=5";
            _ -> ""
          end,
        print_depth_tip(),
        NoLocEvent = Event#event{location = []},
        Label = concuerror_io_lib:pretty_s({I, NoLocEvent}, PrintDepth - 19),
        to_file(
          GraphFile,
          "    \"~p\" [label=\"~s\\l\"~s];~n",
          [Ref, Label, ErrorS]),
        case Sibling =:= none of
          true ->
            to_file(GraphFile, "~s [weight=1000];~n", [ref_edge(Parent, Ref)]);
          false ->
            to_file(
              GraphFile,
              "~s [style=invis,weight=1];~n"
              "~s [constraint=false];~n",
              [ref_edge(Parent, Ref), ref_edge(Sibling, Ref)])
        end,
        {GraphFile, Ref, none};
      {race, EarlyRef, Ref} ->
        to_file(
          GraphFile,
          "~s [constraint=false, color=red, dir=back, penwidth=3,"
          " style=dashed];~n",
          [dref_edge(EarlyRef, Ref)]),
        Graph;
      {set_node, {I, _} = NewParent, NewSibling} ->
        to_file(
          GraphFile,
          "  }~n"
          "  subgraph interleaving_~w {~n",
          [I + 1]),
        {GraphFile, NewParent, NewSibling};
      {status, Count, String, Color} ->
        Final = {Count + 1, final},
        to_file(
          GraphFile,
          "    \"~p\" [label=\"~p: ~s\",style=filled,fillcolor=~s];~n"
          "~s [weight=1000];~n",
          [Final, Count+1, String, Color, ref_edge(Parent, Final)]),
        Graph
    end,
  State#logger_state{graph_data = NewGraph}.

ref_edge(RefA, RefB) ->
  io_lib:format("    \"~p\" -> \"~p\"", [RefA, RefB]).

dref_edge(RefA, RefB) ->
  io_lib:format("    \"~p\":e -> \"~p\":e", [RefA, RefB]).

close_files(State) ->
  graph_close(State),
  file_close(State#logger_state.output).

graph_close(#logger_state{graph_data = disable}) -> ok;
graph_close(#logger_state{graph_data = {GraphFile, _, _}}) ->
  to_file(
    GraphFile,
    "  }~n"
    "}~n", []),
  file_close(GraphFile).

file_close(disable) ->
  ok;
file_close(File) ->
  ok = file:close(File).

%%------------------------------------------------------------------------------

print_depth_tip() ->
  Tip = "Increase '--print_depth' if output/graph contains \"...\".~n",
  ?unique(self(), ?ltip, Tip, []).

%%------------------------------------------------------------------------------

setup_symbolic_names(SymbolicNames, Processes) ->
  case SymbolicNames of
    false -> ok;
    true ->
      print_symbolic_info(),
      concuerror_callback:setup_logger(Processes)
  end.

print_symbolic_info() ->
  Tip =
    "Showing PIDs as \"<symbolic name(/last registered name)>\""
    " ('-h symbolic_names').~n",
  ?unique(self(), ?linfo, Tip, []).