locus_logger.erl

%% Copyright (c) 2017-2024 Guilherme Andrade
%%
%% Permission is hereby granted, free of charge, to any person obtaining a
%% copy  of this software and associated documentation files (the "Software"),
%% to deal in the Software without restriction, including without limitation
%% the rights to use, copy, modify, merge, publish, distribute, sublicense,
%% and/or sell copies of the Software, and to permit persons to whom the
%% Software is furnished to do so, subject to the following conditions:
%%
%% The above copyright notice and this permission notice shall be included in
%% all copies or substantial portions of the Software.
%%
%% THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
%% IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
%% FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
%% AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
%% LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
%% FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
%% DEALINGS IN THE SOFTWARE.
%%
%% locus is an independent project and has not been authorized, sponsored,
%% or otherwise approved by MaxMind.

%% @doc Logging of `locus_database' events; can be adjusted in app config
%% as well as at run time.
-module(locus_logger).
-behaviour(locus_event_subscriber).

%% ------------------------------------------------------------------
%% API Function Exports
%% ------------------------------------------------------------------

-export([on_app_start/0]).
-export([set_loglevel/1]).              -ignore_xref({set_loglevel, 1}).

%% ------------------------------------------------------------------
%% locus_event_subscriber Function Exports
%% ------------------------------------------------------------------

-export([report/2]).

%% ------------------------------------------------------------------
%% Private Function Exports
%% ------------------------------------------------------------------

-ifdef(ESCRIPTIZING).
-export([log_warning/2]).
-endif.

%% ------------------------------------------------------------------
%% Macro Definitions
%% ------------------------------------------------------------------

-define(LOGGING_LEVELS,
        (#{ debug => ?debug,
            info => ?info,
            warning => ?warning,
            error => ?error
         })).

-define(debug, 0).
-define(info, 1).
-define(warning, 2).
-define(error, 3).

-define(is_loglevel(V),
        ((V) =:= debug orelse
         (V) =:= info orelse
         (V) =:= warning orelse
         (V) =:= error orelse
         (V) =:= none)).

-define(case_match(Value, Pattern, Then, OrElse),
        (case (Value) of (Pattern) -> (Then); _ -> (OrElse) end)).

-define(is_http_download_event(Event),
        (element(1, (Event)) =:= request_sent orelse
         element(1, (Event)) =:= download_dismissed orelse
         element(1, (Event)) =:= download_failed_to_start orelse
         element(1, (Event)) =:= download_redirected orelse
         element(1, (Event)) =:= download_started orelse
         element(1, (Event)) =:= download_finished)).

-define(MAX_TRUNCATED_URL_LENGTH, 500).

%% ------------------------------------------------------------------
%% API Function Definitions
%% ------------------------------------------------------------------

-spec on_app_start() -> ok.
%% @private
on_app_start() ->
    CurrentLevel = application:get_env(locus, log_level, undefined),
    _ = logger:set_application_level(locus, CurrentLevel),
    ok.

%% @doc Changes the logging verbosity in runtime
%%
%% `Level' must be either `debug', `info', `warning', `error' or `none'.
-spec set_loglevel(debug | info | warning | error | none) -> ok.
set_loglevel(Level) when ?is_loglevel(Level) ->
    application:set_env(locus, log_level, Level),
    _ = logger:set_application_level(locus, Level),
    ok.

%% ------------------------------------------------------------------
%% locus_event_subscriber Function Definitions
%% ------------------------------------------------------------------

%% @private
-spec report(atom(), locus_event_subscriber:event()) -> ok.
report(DatabaseId, Event) ->
    MinLevel = application:get_env(locus, log_level, undefined),
    MinWeight = maps:get(MinLevel, ?LOGGING_LEVELS, infinity),
    report(MinWeight, DatabaseId, Event).

%% ------------------------------------------------------------------
%% Internal Function Definitions
%% ------------------------------------------------------------------

-spec report(non_neg_integer() | infinity, atom(), locus_event_subscriber:event()) -> ok.
report(MinWeight, DatabaseId, Event)
  when ?is_http_download_event(Event) ->
    report_http_download_event(MinWeight, DatabaseId, database, Event);
report(MinWeight, DatabaseId, {checksum, ChecksumEvent})
  when ?is_http_download_event(ChecksumEvent) ->
    report_http_download_event(MinWeight, DatabaseId, checksum, ChecksumEvent);
report(MinWeight, DatabaseId, {load_attempt_started, Source}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] database load attempt started from ~p", [DatabaseId, Source]);
       MinWeight =< ?info ->
           log_info("[~ts] database load attempt started (~p)",
                    [DatabaseId, resumed_source(Source)]);
       true ->
           ok
    end;
report(MinWeight, DatabaseId, {load_attempt_dismissed, _Source}) ->
    if MinWeight =< ?info ->
           log_info("[~ts] database load attempt dismissed", [DatabaseId]);
       true ->
           ok
    end;
report(MinWeight, DatabaseId, {load_attempt_finished, Source, {ok, Version}}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] database version ~p loaded from ~p", [DatabaseId, Version, Source]);
       MinWeight =< ?info ->
           log_info("[~ts] database version ~p loaded (~p)",
                    [DatabaseId, Version, resumed_source(Source)]);
       true ->
           ok
    end;
report(MinWeight, DatabaseId, {load_attempt_finished, Source, {error, Reason}}) ->
    {Weight, LogFun}= ?case_match(Source, {cache, _},
                                  {?warning, fun log_warning/2},
                                  {?error, fun log_error/2}),
    if MinWeight =< ?debug ->
           LogFun("[~ts] database failed to load from ~p: ~p", [DatabaseId, Source, Reason]);
       MinWeight =< Weight ->
           LogFun("[~ts] database failed to load (~p): ~p",
                  [DatabaseId, resumed_source(Source), Reason]);
       true ->
           ok
    end;
report(MinWeight, DatabaseId, {cache_attempt_finished, Filename, ok}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] database cached at \"~ts\"", [DatabaseId, Filename]);
       MinWeight =< ?info ->
           log_info("[~ts] database cached", [DatabaseId]);
       true ->
           ok
    end;
report(MinWeight, DatabaseId, {cache_attempt_finished, Filename, {error, Reason}}) ->
    if MinWeight =< ?debug ->
           log_error("[~ts] database failed to cache in \"~ts\": ~p",
                     [DatabaseId, Filename, Reason]);
       MinWeight =< ?error  ->
           log_error("[~ts] database failed to cache: ~p",
                     [DatabaseId, Reason]);
       true ->
           ok
    end.

-spec report_http_download_event(non_neg_integer() | infinity, atom(), checksum | database,
                                 locus_http_download:event()) -> ok.
report_http_download_event(MinWeight, DatabaseId, DownloadType, {request_sent, URL, Headers}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] ~s download request sent to \"~ts\" (headers: ~p)",
                    [DatabaseId, DownloadType, URL, Headers]);
       MinWeight =< ?info ->
           MaybeTruncatedURL = maybe_truncate_url(URL),
           log_info("[~ts] ~s download request sent to \"~ts\"",
                    [DatabaseId, DownloadType, MaybeTruncatedURL]);
       true ->
           ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_dismissed, HttpResponse}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] ~s download dismissed: ~p", [DatabaseId, DownloadType, HttpResponse]);
       MinWeight =< ?info ->
           log_info("[~ts] ~s download dismissed", [DatabaseId, DownloadType]);
       true ->
           ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_redirected, Redirection}) ->
    #{permanence := Permanence} = Redirection,
    case Permanence of
        permanent when MinWeight =< ?warning ->
            log_warning("[~ts] ~s download permanently redirected", [DatabaseId, DownloadType]);
        temporary when MinWeight =< ?info ->
            log_warning("[~ts] ~s download temporarily redirected", [DatabaseId, DownloadType]);
        _ ->
            ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_failed_to_start, Reason}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] ~s download failed to start: ~p", [DatabaseId, DownloadType, Reason]);
       MinWeight =< ?info ->
           FormattedReason = simpler_reason_for_download_failing_to_start(Reason),
           log_info("[~ts] ~s download failed to start: ~p", [DatabaseId, DownloadType,
                                                              FormattedReason]);
       true ->
           ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_started, Headers}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] ~s download started (headers ~p)", [DatabaseId, DownloadType, Headers]);
       MinWeight =< ?info ->
           log_info("[~ts] ~s download started", [DatabaseId, DownloadType]);
       true ->
           ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_finished, BodySize, {ok, TrailingHeaders}}) ->
    if MinWeight =< ?debug ->
           log_info("[~ts] ~s download succeeded after ~b bytes (trailing headers ~p)",
                     [DatabaseId, DownloadType, BodySize, TrailingHeaders]);
       MinWeight =< ?info ->
           log_info("[~ts] ~s download succeeded after ~b bytes",
                     [DatabaseId, DownloadType, BodySize]);
       true ->
           ok
    end;
report_http_download_event(MinWeight, DatabaseId, DownloadType,
                           {download_finished, BodySize, {error, Reason}}) ->
    if MinWeight =< ?info ->
           log_info("[~ts] ~s download failed after ~b bytes: ~p",
                    [DatabaseId, DownloadType, BodySize, Reason]);
       true ->
           ok
    end.

log_info(Fmt, Args) ->
    case use_error_logger() of
        true -> log_to_error_logger(info_msg, Fmt, Args);
        false -> log_to_logger(info, Fmt, Args)
    end.

-spec log_warning(string(), list()) -> ok.
%% @private
log_warning(Fmt, Args) ->
    case use_error_logger() of
        true -> log_to_error_logger(warning_msg, Fmt, Args);
        false -> log_to_logger(warning, Fmt, Args)
    end.

log_error(Fmt, Args) ->
    case use_error_logger() of
        true -> log_to_error_logger(error_msg, Fmt, Args);
        false -> log_to_logger(error, Fmt, Args)
    end.

log_to_logger(Fun, Fmt, Args) ->
    FullFmt = "[locus] " ++ Fmt,
    logger:Fun(FullFmt, Args).

% `lager' and `logger' don`t play nice with each other (as of Jun 2019)
% * https://github.com/erlang-lager/lager/issues/492
% * https://github.com/erlang-lager/lager/pull/488
use_error_logger() ->
    has_lager() andalso not has_usable_logger().

% Taken from: https://github.com/ferd/cth_readable/pull/23
has_lager() ->
    % Module is present
    erlang:function_exported(logger, module_info, 0).

% Taken from: https://github.com/ferd/cth_readable/pull/23
has_usable_logger() ->
    %% The config is set (lager didn't remove it)
    erlang:function_exported(logger, get_handler_config, 1) andalso
    logger:get_handler_config(default) =/= {error, {not_found, default}}.

log_to_error_logger(Fun, Fmt, Args) ->
    FullFmt = "[locus] " ++ Fmt ++ "~n",
    error_logger:(Fun)(FullFmt, Args).

-spec maybe_truncate_url(locus_http_download:url()) -> locus_http_download:url().
maybe_truncate_url(URL) ->
    TruncationSuffix = "...",
    Threshold = ?MAX_TRUNCATED_URL_LENGTH - length(TruncationSuffix),
    case length(URL) >= Threshold of
        true ->
            lists:sublist(URL, Threshold) ++ TruncationSuffix;
        false ->
            URL
    end.

-spec resumed_source(locus_loader:source()) -> cache | remote | filesystem | local.
resumed_source({SourceType, _SourceLocation}) ->
    SourceType.

-spec simpler_reason_for_download_failing_to_start(
        locus_http_download:reason_for_download_failing_to_start()
       ) -> _.
simpler_reason_for_download_failing_to_start(Reason) ->
    case Reason of
        {http, Status, _Headers, Body} ->
            {Status, Body};
        too_many_redirections ->
            Reason;
        {invalid_redirection, _} ->
            Reason;
        {error, _} = Error ->
            Error;
        timeout ->
            timeout
    end.