From 9a6aff40a7155f74b4e981316159be3a9d2352af Mon Sep 17 00:00:00 2001 From: Scott Lystig Fritchie Date: Thu, 18 Aug 2011 17:07:53 -0500 Subject: [PATCH 1/4] Add lager:log() message size truncation Use lager_trunc_io:format() for all messages submitted via lager:log(). Also, refactor list flattening and final newline stripping into shared func that uses re:replace() to do both. --- src/lager.erl | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index cbd07b7..cb91aab 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -53,8 +53,9 @@ start_ok(App, {error, Reason}) -> ok | {error, lager_not_running}. log(Level, Module, Function, Line, Pid, Time, Message) -> Timestamp = lager_util:format_time(Time), - Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, - Function, Line]), string:strip(lists:flatten(Message), right, $\n)], + Msg = [["[", atom_to_list(Level), "] "], + io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), + string_reduce(Message)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @private @@ -64,7 +65,7 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - string:strip(lists:flatten(io_lib:format(Format, Args)), right, $\n)], + string_reduce(lager_trunc_io:format(Format, Args, 4096))], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -72,7 +73,7 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) -> log(Level, Pid, Message) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - string:strip(lists:flatten(Message), right, $\n)], + string_reduce(Message)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -80,7 +81,7 @@ log(Level, Pid, Message) -> log(Level, Pid, Format, Args) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - string:strip(lists:flatten(io_lib:format(Format, Args)), right, $\n)], + string_reduce(lager_trunc_io:format(Format, Args, 4096))], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Set the loglevel for a particular backend. @@ -117,7 +118,7 @@ posix_error(Error) when is_atom(Error) -> Message -> Message end; posix_error(Error) -> - lists:flatten(io_lib:format("~p", [Error])). + lists:flatten(lager_trunc_io:format("~p", [Error], 4096)). %% @private get_loglevels() -> @@ -139,3 +140,6 @@ safe_notify(Level, Timestamp, Msg) -> gen_event:sync_notify(Pid, {log, Level, Timestamp, Msg}) end. +%% @private +string_reduce(IOdata) -> + re:replace(IOdata, "\n$", "", [{return, list}]). From eea29bece1c042ec5c9fafbb8e9faeb01d1b7d5c Mon Sep 17 00:00:00 2001 From: Scott Lystig Fritchie Date: Mon, 22 Aug 2011 16:31:16 -0500 Subject: [PATCH 2/4] Rework using safe_format() from one of Andrew's branches --- src/lager.erl | 28 ++++++++++++++++++++-------- 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index cb91aab..7f15f8c 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -55,7 +55,7 @@ log(Level, Module, Function, Line, Pid, Time, Message) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - string_reduce(Message)], + format_string_chop("~s", [Message], 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @private @@ -64,8 +64,8 @@ log(Level, Module, Function, Line, Pid, Time, Message) -> log(Level, Module, Function, Line, Pid, Time, Format, Args) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], - io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - string_reduce(lager_trunc_io:format(Format, Args, 4096))], + io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), + format_string_chop(Format, Args, 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -73,7 +73,7 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) -> log(Level, Pid, Message) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - string_reduce(Message)], + format_string_chop("~s", [Message], 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -81,7 +81,7 @@ log(Level, Pid, Message) -> log(Level, Pid, Format, Args) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - string_reduce(lager_trunc_io:format(Format, Args, 4096))], + format_string_chop(Format, Args, 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Set the loglevel for a particular backend. @@ -118,7 +118,7 @@ posix_error(Error) when is_atom(Error) -> Message -> Message end; posix_error(Error) -> - lists:flatten(lager_trunc_io:format("~p", [Error], 4096)). + format_string_chop("~p", [Error], 4096). %% @private get_loglevels() -> @@ -140,6 +140,18 @@ safe_notify(Level, Timestamp, Msg) -> gen_event:sync_notify(Pid, {log, Level, Timestamp, Msg}) end. +%% @doc Print the format string `Fmt' with `Args' safely with a size +%% limit of `Limit'. If the format string is invalid, or not enough +%% arguments are supplied 'FORMAT ERROR' is printed with the offending +%% arguments. The caller is NOT crashed. + +safe_format(Fmt, Args, Limit) -> + try lager_trunc_io:format(Fmt, Args, Limit) of + Result -> Result + catch + _:_ -> lager_trunc_io:format("FORMAT ERROR: ~p ~p", [Fmt, Args], Limit) + end. + %% @private -string_reduce(IOdata) -> - re:replace(IOdata, "\n$", "", [{return, list}]). +format_string_chop(Fmt, Args, Limit) -> + re:replace(safe_format(Fmt, Args, Limit), "\n$", "", [{return, list}]). From cf51ba06d371d92ae06a3c438d4650cf2788c11e Mon Sep 17 00:00:00 2001 From: Scott Lystig Fritchie Date: Mon, 22 Aug 2011 16:34:56 -0500 Subject: [PATCH 3/4] Rename format_string_chop() -> safe_format_chop(), add -export --- src/lager.erl | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 7f15f8c..c1cd4d0 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -24,7 +24,8 @@ -export([start/0, log/7, log/8, log/3, log/4, get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, - minimum_loglevel/1, posix_error/1]). + minimum_loglevel/1, posix_error/1, + safe_format/3, safe_format_chop/3]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -55,7 +56,7 @@ log(Level, Module, Function, Line, Pid, Time, Message) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - format_string_chop("~s", [Message], 4096)], + safe_format_chop("~s", [Message], 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @private @@ -65,7 +66,7 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - format_string_chop(Format, Args, 4096)], + safe_format_chop(Format, Args, 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -73,7 +74,7 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) -> log(Level, Pid, Message) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - format_string_chop("~s", [Message], 4096)], + safe_format_chop("~s", [Message], 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Manually log a message into lager without using the parse transform. @@ -81,7 +82,7 @@ log(Level, Pid, Message) -> log(Level, Pid, Format, Args) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - format_string_chop(Format, Args, 4096)], + safe_format_chop(Format, Args, 4096)], safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). %% @doc Set the loglevel for a particular backend. @@ -118,7 +119,7 @@ posix_error(Error) when is_atom(Error) -> Message -> Message end; posix_error(Error) -> - format_string_chop("~p", [Error], 4096). + safe_format_chop("~p", [Error], 4096). %% @private get_loglevels() -> @@ -153,5 +154,5 @@ safe_format(Fmt, Args, Limit) -> end. %% @private -format_string_chop(Fmt, Args, Limit) -> +safe_format_chop(Fmt, Args, Limit) -> re:replace(safe_format(Fmt, Args, Limit), "\n$", "", [{return, list}]). From 83c2a412ab23ea9e88e7abbf633fc116a82ea872 Mon Sep 17 00:00:00 2001 From: Scott Lystig Fritchie Date: Mon, 22 Aug 2011 16:58:42 -0500 Subject: [PATCH 4/4] Mash in the remainder of adt-error-format-protection branch --- src/error_logger_lager_h.erl | 6 +++--- src/lager_crash_log.erl | 2 +- test/lager_test_backend.erl | 6 ++++++ 3 files changed, 10 insertions(+), 4 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 41141e6..5983bdb 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -80,7 +80,7 @@ handle_event(Event, State) -> [ID, Name, format_reason(Reason)]); _ -> ?CRASH_LOG(Event), - ?LOG(error, Pid, lager_trunc_io:format(Fmt, Args, 4096)) + ?LOG(error, Pid, lager:safe_format(Fmt, Args, 4096)) end; {error_report, _GL, {Pid, std_error, D}} -> ?CRASH_LOG(Event), @@ -100,11 +100,11 @@ handle_event(Event, State) -> ?CRASH_LOG(Event), ?LOG(error, Pid, ["CRASH REPORT ", format_crash_report(Self, Neighbours)]); {warning_msg, _GL, {Pid, Fmt, Args}} -> - ?LOG(warning, Pid, lager_trunc_io:format(Fmt, Args, 4096)); + ?LOG(warning, Pid, lager:safe_format(Fmt, Args, 4096)); {warning_report, _GL, {Pid, std_warning, Report}} -> ?LOG(warning, Pid, print_silly_list(Report)); {info_msg, _GL, {Pid, Fmt, Args}} -> - ?LOG(info, Pid, lager_trunc_io:format(Fmt, Args, 4096)); + ?LOG(info, Pid, lager:safe_format(Fmt, Args, 4096)); {info_report, _GL, {Pid, std_info, D}} when is_list(D) -> Details = lists:sort(D), case Details of diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index 81e553d..af673ce 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -166,7 +166,7 @@ schedule_rotation(Date) -> %% to limit the formatted string's size. limited_fmt(Fmt, Args, FmtMaxBytes) -> - lager_trunc_io:format(Fmt, Args, FmtMaxBytes). + lager:safe_format(Fmt, Args, FmtMaxBytes). limited_str(Term, FmtMaxBytes) -> {Str, _} = lager_trunc_io:print(Term, FmtMaxBytes), diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 77c1d75..9e638af 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -647,6 +647,12 @@ error_logger_redirect_test_() -> ] }. +safe_format_test() -> + ?assertEqual("foo bar", lists:flatten(lager:safe_format("~p ~p", [foo, bar], 1024))), + ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))), + ?assertEqual("FORMAT ERROR: \"~s\" [1]", lists:flatten(lager:safe_format("~s", [1], 1024))), + ok. + -endif.