Merge pull request #278 from basho/unsafe_format

Add an unsafe_formatting code path

Reviewed-by: JeetKunDoug

README.md

@@ -20,6 +20,7 @@ Features
 * Rewrites common OTP error messages into more readable messages
 * Support for pretty printing records encountered at compile time
 * Tolerant in the face of large or many log messages, won't out of memory the node
+* Optional feature to bypass log size truncation ("unsafe")
 * Supports internal time and date based rotation, as well as external rotation tools
 * Syslog style log level comparison flags
 * Colored terminal output (requires R16+)
@@ -263,6 +264,30 @@ related processes crash, you can set a limit:
 
 It is probably best to keep this number small.
 
+"Unsafe"
+--------
+The unsafe code pathway bypasses the normal lager formatting code and uses the
+same code as error_logger in OTP. This provides a marginal speedup to your logging
+code (we measured between 0.5-1.3% improvement during our benchmarking; others have
+reported better improvements.)
+
+This is a **dangerous** feature. It *will not* protect you against
+large log messages - large messages can kill your application and even your
+Erlang VM dead due to memory exhaustion as large terms are copied over and
+over in a failure cascade.  We strongly recommend that this code pathway
+only be used by log messages with a well bounded upper size of around 500 bytes.
+
+If there's any possibility the log messages could exceed that limit, you should
+use the normal lager message formatting code which will provide the appropriate
+size limitations and protection against memory exhaustion.
+
+If you want to format an unsafe log message, you may use the severity level (as
+usual) followed by `_unsafe`. Here's an example:
+
+```erlang
+lager:info_unsafe("The quick brown ~s jumped over the lazy ~s", ["fox", "dog"]).
+```
+
 Runtime loglevel changes
 ------------------------
 You can change the log level of any lager backend at runtime by doing the

include/lager.hrl

@@ -22,6 +22,11 @@
 -define(LEVELS,
     [debug, info, notice, warning, error, critical, alert, emergency, none]).
 
+%% Use of these "functions" means that the argument list will not be
+%% truncated for safety
+-define(LEVELS_UNSAFE,
+    [{debug_unsafe, debug}, {info_unsafe, info}, {notice_unsafe, notice}, {warning_unsafe, warning}, {error_unsafe, error}, {critical_unsafe, critical}, {alert_unsafe, alert}, {emergency_unsafe, emergency}]).
+
 -define(DEBUG, 128).
 -define(INFO, 64).
 -define(NOTICE, 32).
@@ -64,7 +69,7 @@
             Level,
             [{pid,Pid},{line,?LINE},{file,?FILE},{module,?MODULE}],
             [])}
-        )). 
+        )).
 
 %% FOR INTERNAL USE ONLY
 %% internal non-blocking logging call
@@ -102,14 +107,14 @@
 -endif.
 
 -record(lager_shaper, {
-		  %% how many messages per second we try to deliver
-		  hwm = undefined :: 'undefined' | pos_integer(),
-		  %% how many messages we've received this second
-		  mps = 0 :: non_neg_integer(),
-		  %% the current second
-		  lasttime = os:timestamp() :: erlang:timestamp(),
-		  %% count of dropped messages this second
-		  dropped = 0 :: non_neg_integer()
-		 }).
+                  %% how many messages per second we try to deliver
+                  hwm = undefined :: 'undefined' | pos_integer(),
+                  %% how many messages we've received this second
+                  mps = 0 :: non_neg_integer(),
+                  %% the current second
+                  lasttime = os:timestamp() :: erlang:timestamp(),
+                  %% count of dropped messages this second
+                  dropped = 0 :: non_neg_integer()
+                 }).
 
 -type lager_shaper() :: #lager_shaper{}.

src/lager.erl

@@ -26,13 +26,14 @@
 %% API
 -export([start/0,
         log/3, log/4, log/5,
+        log_unsafe/4,
         md/0, md/1,
         trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2,
         name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0,
         get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1,
         update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4,
-        safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9,
-        do_log/9, do_log/10, pr/2, pr/3]).
+        safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9,
+        do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3]).
 
 -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency.
 -type log_level_number() :: 0..7.
@@ -83,21 +84,27 @@ md(_) ->
     erlang:error(badarg).
 
 
--spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) ->  ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}.
+-spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer(), safe | unsafe) ->  ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}.
 %% this is the same check that the parse transform bakes into the module at compile time
 %% see lager_transform (lines 173-216)
-dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
+dispatch_log(Sink, Severity, Metadata, Format, Args, Size, Safety) when is_atom(Severity)->
     SeverityAsInt=lager_util:level_to_num(Severity),
     case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of
          {undefined, undefined, _} -> {error, lager_not_running};
          {undefined, _LagerEventPid0, _} -> {error, {sink_not_configured, Sink}};
-         {SinkPid, _LagerEventPid1, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] ->
+         {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= safe andalso ( (Level band SeverityAsInt) /= 0 orelse Traces /= [] ) ->
             do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid);
+         {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= unsafe andalso ( (Level band SeverityAsInt) /= 0 orelse Traces /= [] ) ->
+            do_log_unsafe(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid);
          _ -> ok
     end.
 
 %% @private Should only be called externally from code generated from the parse transform
 do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) ->
+    FormatFun = fun() -> safe_format_chop(Format, Args, Size) end,
+    do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun).
+
+do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun) ->
     {Destinations, TraceSinkPid} = case TraceFilters of
         [] ->
             {[], undefined};
@@ -108,7 +115,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr
         true ->
             Msg = case Args of
                 A when is_list(A) ->
-                    safe_format_chop(Format,Args,Size);
+                    FormatFun();
                 _ ->
                     Format
             end,
@@ -130,13 +137,20 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr
             ok
     end.
 
+%% @private Should only be called externally from code generated from the parse transform
+%% Specifically, it would be level ++ `_unsafe' as in `info_unsafe'.
+do_log_unsafe(Severity, Metadata, Format, Args, _Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) ->
+    FormatFun = fun() -> unsafe_format(Format, Args) end,
+    do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun).
+
+
 %% backwards compatible with beams compiled with lager 1.x
 dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, Size) ->
     dispatch_log(Severity, Metadata, Format, Args, Size).
 
 %% backwards compatible with beams compiled with lager 2.x
 dispatch_log(Severity, Metadata, Format, Args, Size) ->
-    dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size).
+    dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size, safe).
 
 %% backwards compatible with beams compiled with lager 2.x
 do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, SinkPid) ->
@@ -162,12 +176,16 @@ log(Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) ->
 log(Level, Metadata, Format, Args) when is_list(Metadata) ->
     dispatch_log(Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION).
 
+log_unsafe(Level, Metadata, Format, Args) when is_list(Metadata) ->
+    dispatch_log(?DEFAULT_SINK, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION, unsafe).
+
+
 %% @doc Manually log a message into lager without using the parse transform.
 -spec log(atom(), log_level(), pid() | atom() | [tuple(),...], string(), list()) -> ok | {error, lager_not_running}.
 log(Sink, Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) ->
-    dispatch_log(Sink, Level, [{pid,Pid}], Format, Args, ?DEFAULT_TRUNCATION);
+    dispatch_log(Sink, Level, [{pid,Pid}], Format, Args, ?DEFAULT_TRUNCATION, safe);
 log(Sink, Level, Metadata, Format, Args) when is_list(Metadata) ->
-    dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION).
+    dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION, safe).
 
 validate_trace_filters(Filters, Level, Backend) ->
     Sink = proplists:get_value(sink, Filters, ?DEFAULT_SINK),
@@ -486,6 +504,23 @@ safe_format(Fmt, Args, Limit, Options) ->
 safe_format_chop(Fmt, Args, Limit) ->
     safe_format(Fmt, Args, Limit, [{chomp, true}]).
 
+%% @private Print the format string `Fmt' with `Args' without a size limit.
+%% This is unsafe because the output of this function is unbounded.
+%%
+%% Log messages with unbounded size will kill your application dead as
+%% OTP mechanisms stuggle to cope with them.  So this function is
+%% intended <b>only</b> for messages which have a reasonable bounded
+%% size before they're formatted.
+%%
+%% If the format string is invalid or not enough arguments are
+%% supplied a 'FORMAT ERROR' message is printed instead with the
+%% offending arguments. The caller is NOT crashed.
+unsafe_format(Fmt, Args) ->
+    try io_lib:format(Fmt, Args)
+    catch
+        _:_ -> io_lib:format("FORMAT ERROR: ~p ~p", [Fmt, Args])
+    end.
+
 %% @doc Print a record lager found during parse transform
 pr(Record, Module) when is_tuple(Record), is_atom(element(1, Record)) ->
     pr(Record, Module, []);

src/lager_transform.erl

@@ -89,7 +89,13 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module},
                     SinkName = list_to_atom(atom_to_list(Module) ++ "_event"),
                     do_transform(Line, SinkName, Function, Arguments0);
                 false ->
-                    Stmt
+                    case lists:keyfind(Function, 1, ?LEVELS_UNSAFE) of
+                        {Function, Severity} ->
+                            SinkName = list_to_atom(atom_to_list(Module) ++ "_event"),
+                            do_transform(Line, SinkName, Severity, Arguments0, unsafe);
+                        false ->
+                            Stmt
+                    end
             end;
         false ->
             list_to_tuple(transform_statement(tuple_to_list(Stmt), Sinks))
@@ -102,6 +108,9 @@ transform_statement(Stmt, _Sinks) ->
     Stmt.
 
 do_transform(Line, SinkName, Severity, Arguments0) ->
+    do_transform(Line, SinkName, Severity, Arguments0, safe).
+
+do_transform(Line, SinkName, Severity, Arguments0, Safety) ->
     SeverityAsInt=lager_util:level_to_num(Severity),
     DefaultAttrs0 = {cons, Line, {tuple, Line, [
                                                 {atom, Line, module}, {atom, Line, get(module)}]},
@@ -168,6 +177,12 @@ do_transform(Line, SinkName, Severity, Arguments0) ->
     LevelVar = make_varname("__Level", Line),
     TracesVar = make_varname("__Traces", Line),
     PidVar = make_varname("__Pid", Line),
+    LogFun = case Safety of
+                 safe ->
+                     do_log;
+                 unsafe ->
+                     do_log_unsafe
+             end,
     %% Wrap the call to lager:dispatch_log/6 in case that will avoid doing any work if this message is not elegible for logging
     %% See lager.erl (lines 89-100) for lager:dispatch_log/6
     %% case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of
@@ -205,7 +220,7 @@ do_transform(Line, SinkName, Severity, Arguments0) ->
                   [[{op, Line, 'orelse',
                     {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}},
                     {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]],
-                  [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, do_log}},
+                  [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, LogFun}},
                          [{atom,Line,Severity},
                           Meta,
                           Message,

test/lager_test_backend.erl

@@ -168,11 +168,11 @@ lager_test_() ->
                         ?assertEqual(0, count())
                 end
             },
-        {"test sink not running",
-        fun() ->
-            ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running"))
-        end
-        },
+            {"test sink not running",
+                fun() ->
+                         ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running"))
+                end
+            },
             {"logging works",
                 fun() ->
                         lager:warning("test message"),
@@ -183,6 +183,16 @@ lager_test_() ->
                         ok
                 end
             },
+            {"unsafe logging works",
+                fun() ->
+                        lager:warning_unsafe("test message"),
+                        ?assertEqual(1, count()),
+                        {Level, _Time, Message, _Metadata}  = pop(),
+                        ?assertMatch(Level, lager_util:level_to_num(warning)),
+                        ?assertEqual("test message", Message),
+                        ok
+                end
+            },
             {"logging with arguments works",
                 fun() ->
                         lager:warning("test message ~p", [self()]),
@@ -193,6 +203,16 @@ lager_test_() ->
                         ok
                 end
             },
+            {"unsafe logging with args works",
+                fun() ->
+                        lager:warning("test message ~p", [self()]),
+                        ?assertEqual(1, count()),
+                        {Level, _Time, Message,_Metadata}  = pop(),
+                        ?assertMatch(Level, lager_util:level_to_num(warning)),
+                        ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
+                        ok
+                end
+            },
             {"logging works from inside a begin/end block",
                 fun() ->
                         ?assertEqual(0, count()),
@@ -592,6 +612,13 @@ lager_test_() ->
                         ok
                 end
             },
+            {"unsafe messages really are not truncated",
+                fun() ->
+                        lager:info_unsafe("doom, doom has come upon you all ~p", [string:copies("doom", 1500)]),
+                        {_, _, Msg,_Metadata} = pop(),
+                        ?assert(length(lists:flatten(Msg)) == 6035)
+                end
+            },
             {"can't store invalid metadata",
                 fun() ->
                         ?assertEqual(ok, lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}])),
@@ -881,7 +908,6 @@ error_logger_redirect_test_() ->
                         ?assertEqual("Привет!", lists:flatten(Msg))
                 end
             },
-
             {"error messages are truncated at 4096 characters",
                 fun() ->
                         sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
@@ -890,6 +916,7 @@ error_logger_redirect_test_() ->
                         ?assert(length(lists:flatten(Msg)) < 5100)
                 end
             },
+
             {"info reports are printed",
                 fun() ->
                         sync_error_logger:info_report([{this, is}, a, {silly, format}]),
@@ -1349,6 +1376,11 @@ safe_format_test() ->
     ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))),
     ok.
 
+unsafe_format_test() ->
+    ?assertEqual("foo bar", lists:flatten(lager:unsafe_format("~p ~p", [foo, bar]))),
+    ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:unsafe_format("~p ~p ~p", [foo, bar]))),
+    ok.
+
 async_threshold_test_() ->
     {foreach,
         fun() ->