locus

%% Copyright (c) 2017-2026 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,
    apply(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",
    apply(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.