Merge branch 'slf-log-msg-truncation'

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

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.
@@ -53,8 +54,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]),
+           safe_format_chop("~s", [Message], 4096)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
 %% @private
@@ -63,8 +65,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]),
-         class="nn">string class="p">: class="nf">strip(listsan class="p">:flatten(io_lib:format(Format, Args)), right, $\n)],
+           io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]),
+           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.
@@ -72,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]),
-        string:strip(lists:flatten(Message), right, $\n)],
+           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.
@@ -80,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]),
-         class="nn">string class="p">: class="nf">strip(listsan class="p">:flatten(io_lib:format(Format, Args)), right, $\n)],
+           safe_format_chop(Format, Args, 4096)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
 %% @doc Set the loglevel for a particular backend.
@@ -117,7 +119,7 @@ posix_error(Error) when is_atom(Error) ->
         Message -> Message
     end;
 posix_error(Error) ->
-    
listsan>:flatten(io_lib:format("~p", [Error])).
+    safe_format_chop("~p", [Error], 4096).
 
 %% @private
 get_loglevels() ->
@@ -139,3 +141,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
+safe_format_chop(Fmt, Args, Limit) ->
+    re:replace(safe_format(Fmt, Args, Limit), "\n$", "", [{return, list}]).

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),

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.