diff --git a/README.md b/README.md index 5e37514..535e938 100644 --- a/README.md +++ b/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 diff --git a/include/lager.hrl b/include/lager.hrl index 124e17d..82116f0 100644 --- a/include/lager.hrl +++ b/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{}. diff --git a/src/lager.erl b/src/lager.erl index 575e2bb..4c1d677 100644 --- a/src/lager.erl +++ b/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 only 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, []); diff --git a/src/lager_transform.erl b/src/lager_transform.erl index eda84d1..ceddb22 100644 --- a/src/lager_transform.erl +++ b/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, diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 93a69b1..51dd738 100644 --- a/test/lager_test_backend.erl +++ b/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() ->