%% Copyright (c) 2017-2021 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. 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.