diff -Nru erlang-lager-3.0.1/debian/changelog erlang-lager-3.1.0/debian/changelog --- erlang-lager-3.0.1/debian/changelog 2016-03-12 06:41:34.000000000 +0000 +++ erlang-lager-3.1.0/debian/changelog 2016-03-18 02:28:49.000000000 +0000 @@ -1,8 +1,21 @@ -erlang-lager (3.0.1-1~14.04.0) trusty; urgency=medium +erlang-lager (3.1.0-1~14.04.0) trusty; urgency=medium * backport to trusty - -- Richard Hansen Sun, 06 Mar 2016 05:55:24 -0500 + -- Richard Hansen Thu, 17 Mar 2016 22:28:00 -0400 + +erlang-lager (3.1.0-1) unstable; urgency=medium + + * Updated debian/copyright + * Imported Upstream version 3.1.0 + + -- Philipp Huebner Sun, 31 Jan 2016 13:38:21 +0100 + +erlang-lager (3.0.2-1) unstable; urgency=low + + * Imported Upstream version 3.0.2 + + -- Philipp Huebner Sat, 05 Dec 2015 14:47:14 +0100 erlang-lager (3.0.1-1) unstable; urgency=low diff -Nru erlang-lager-3.0.1/debian/copyright erlang-lager-3.1.0/debian/copyright --- erlang-lager-3.0.1/debian/copyright 2016-03-12 06:41:34.000000000 +0000 +++ erlang-lager-3.1.0/debian/copyright 2016-01-31 12:03:24.000000000 +0000 @@ -3,7 +3,7 @@ Source: https://github.com/basho/lager Files: * -Copyright: 2011-2015 Basho Technologies, Inc. +Copyright: 2011-2016 Basho Technologies, Inc. License: Apache-2.0 Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -38,7 +38,7 @@ under the License. Files: debian/* -Copyright: 2014-2015 Philipp Huebner +Copyright: 2014-2016 Philipp Huebner License: GPL-2+ This package is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by diff -Nru erlang-lager-3.0.1/debian/patches/remove-deps.diff erlang-lager-3.1.0/debian/patches/remove-deps.diff --- erlang-lager-3.0.1/debian/patches/remove-deps.diff 2016-03-12 06:41:34.000000000 +0000 +++ erlang-lager-3.1.0/debian/patches/remove-deps.diff 2016-01-31 12:26:40.000000000 +0000 @@ -12,7 +12,7 @@ nowarn_export_all ]}. -{deps, [ -- {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.7"}}} +- {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.8"}}} -]}. {xref_checks, []}. diff -Nru erlang-lager-3.0.1/include/lager.hrl erlang-lager-3.1.0/include/lager.hrl --- erlang-lager-3.0.1/include/lager.hrl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/include/lager.hrl 2016-01-27 21:39:55.000000000 +0000 @@ -18,6 +18,8 @@ -define(DEFAULT_TRUNCATION, 4096). -define(DEFAULT_TRACER, lager_default_tracer). -define(DEFAULT_SINK, lager_event). +-define(ERROR_LOGGER_SINK, error_logger_lager_event). + -define(LEVELS, [debug, info, notice, warning, error, critical, alert, emergency, none]). @@ -61,6 +63,9 @@ ?EMERGENCY -> emergency end). +-define(SHOULD_LOG(Sink, Level), + (lager_util:level_to_num(Level) band element(1, lager_config:get({Sink, loglevel}, {?LOG_NONE, []}))) /= 0). + -define(SHOULD_LOG(Level), (lager_util:level_to_num(Level) band element(1, lager_config:get(loglevel, {?LOG_NONE, []}))) /= 0). diff -Nru erlang-lager-3.0.1/README.md erlang-lager-3.1.0/README.md --- erlang-lager-3.0.1/README.md 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/README.md 2016-01-27 21:39:55.000000000 +0000 @@ -222,6 +222,8 @@ traditional erlang error messages into a friendlier format and sends them into lager itself to be treated like a regular lager log call. To disable this, set the lager application variable `error_logger_redirect` to `false`. +You can also disable reformatting for OTP and Cowboy messages by setting variable +`error_logger_format_raw` to `true`. The `error_logger` handler will also log more complete error messages (protected with use of `trunc_io`) to a "crash log" which can be referred to for further @@ -231,6 +233,23 @@ Messages in the crash log are subject to a maximum message size which can be specified via the `crash_log_msg_size` application variable. +Messages from `error_logger` will be redirected to `error_logger_lager_event` sink +if it is defined so it can be redirected to another log file. +For example: + +``` +[{lager, [ + {extra_sinks, + [ + {error_logger_lager_event, + [{handlers, [ + {lager_file_backend, [{file, "error_logger.log"}, {level, info}]}] + }] + }] + }] +}]. +``` +Will send all `error_logger` messages to `error_logger.log` file. Overload Protection ------------------- @@ -392,6 +411,20 @@ lager available, but they may not have been updated to the new API. As they are updated, links to them can be re-added here. +Exception Pretty Printing +---------------------- + +```erlang +try + foo() +catch + Class:Reason -> + lager:error( + "~nStacktrace:~s", + [lager:pr_stacktrace(erlang:get_stacktrace(), {Class, Reason})]) +end. +``` + Record Pretty Printing ---------------------- Lager's parse transform will keep track of any record definitions it encounters @@ -550,3 +583,23 @@ ``` erlc -pa lager/ebin +'{parse_transform, lager_transform}' +'{lager_truncation_size, 1024}' file.erl ``` + +3.x Changelog +------------- +3.1.0 - 27 January 2016 + + * Feature: API calls to a rotate handler, sink or all. This change + introduces a new `rotate` message for 3rd party lager backends; that's + why this is released as a new minor version number. (#311) + +3.0.3 - 27 January 2016 + + * Feature: Pretty printer for human readable stack traces (#298) + * Feature: Make error reformatting optional (#305) + * Feature: Optional and explicit sink for error_logger messages (#303) + * Bugfix: Always explicitly close a file after its been rotated (#316) + * Bugfix: If a relative path already contains the log root, do not add it again (#317) + * Bugfix: Configure and start extra sinks before traces are evaluated (#307) + * Bugfix: Stop and remove traces correctly (#306) + * Bugfix: A byte value of 255 is valid for Unicode (#300) + * Dependency: Bump to goldrush 0.1.8 (#313) diff -Nru erlang-lager-3.0.1/rebar.config erlang-lager-3.1.0/rebar.config --- erlang-lager-3.0.1/rebar.config 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/rebar.config 2016-01-27 21:39:55.000000000 +0000 @@ -44,7 +44,7 @@ nowarn_export_all ]}. {deps, [ - {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.7"}}} + {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.8"}}} ]}. {xref_checks, []}. diff -Nru erlang-lager-3.0.1/src/error_logger_lager_h.erl erlang-lager-3.1.0/src/error_logger_lager_h.erl --- erlang-lager-3.0.1/src/error_logger_lager_h.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/error_logger_lager_h.erl 2016-01-27 21:39:55.000000000 +0000 @@ -31,26 +31,28 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). --export([format_reason/1]). +-export([format_reason/1, format_mfa/1, format_args/3]). -record(state, { + sink :: atom(), shaper :: lager_shaper(), %% group leader strategy - groupleader_strategy :: handle | ignore | mirror + groupleader_strategy :: handle | ignore | mirror, + raw :: boolean() }). --define(LOGMSG(Level, Pid, Msg), - case ?SHOULD_LOG(Level) of +-define(LOGMSG(Sink, Level, Pid, Msg), + case ?SHOULD_LOG(Sink, Level) of true -> - _ =lager:log(Level, Pid, Msg), + _ =lager:log(Sink, Level, Pid, Msg, []), ok; _ -> ok end). --define(LOGFMT(Level, Pid, Fmt, Args), - case ?SHOULD_LOG(Level) of +-define(LOGFMT(Sink, Level, Pid, Fmt, Args), + case ?SHOULD_LOG(Sink, Level) of true -> - _ = lager:log(Level, Pid, Fmt, Args), + _ = lager:log(Sink, Level, Pid, Fmt, Args), ok; _ -> ok end). @@ -71,7 +73,9 @@ -spec init(any()) -> {ok, #state{}}. init([HighWaterMark, GlStrategy]) -> Shaper = #lager_shaper{hwm=HighWaterMark}, - {ok, #state{shaper=Shaper, groupleader_strategy=GlStrategy}}. + Raw = application:get_env(lager, error_logger_format_raw, false), + Sink = configured_sink(), + {ok, #state{sink=Sink, shaper=Shaper, groupleader_strategy=GlStrategy, raw=Raw}}. handle_call({set_high_water, N}, #state{shaper=Shaper} = State) -> NewShaper = Shaper#lager_shaper{hwm=N}, @@ -79,12 +83,12 @@ handle_call(_Request, State) -> {ok, unknown_call, State}. -handle_event(Event, #state{shaper=Shaper} = State) -> +handle_event(Event, #state{sink=Sink, shaper=Shaper} = State) -> case lager_util:check_hwm(Shaper) of {true, 0, NewShaper} -> eval_gl(Event, State#state{shaper=NewShaper}); {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} when Drop > 0 -> - ?LOGFMT(warning, self(), + ?LOGFMT(Sink, warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, Hwm]), eval_gl(Event, State#state{shaper=NewShaper}); @@ -98,11 +102,29 @@ terminate(_Reason, _State) -> ok. + +code_change(_OldVsn, {state, Shaper, GLStrategy}, _Extra) -> + Raw = application:get_env(lager, error_logger_format_raw, false), + {ok, #state{ + sink=configured_sink(), + shaper=Shaper, + groupleader_strategy=GLStrategy, + raw=Raw + }}; +code_change(_OldVsn, {state, Sink, Shaper, GLS}, _Extra) -> + Raw = application:get_env(lager, error_logger_format_raw, false), + {ok, #state{sink=Sink, shaper=Shaper, groupleader_strategy=GLS, raw=Raw}}; code_change(_OldVsn, State, _Extra) -> {ok, State}. %% internal functions +configured_sink() -> + case proplists:get_value(?ERROR_LOGGER_SINK, application:get_env(lager, extra_sinks, [])) of + undefined -> ?DEFAULT_SINK; + _ -> ?ERROR_LOGGER_SINK + end. + eval_gl(Event, #state{groupleader_strategy=GlStrategy0}=State) when is_pid(element(2, Event)) -> case element(2, Event) of GL when node(GL) =/= node(), GlStrategy0 =:= ignore -> @@ -117,58 +139,59 @@ eval_gl(Event, State) -> log_event(Event, State). -log_event(Event, State) -> +log_event(Event, #state{sink=Sink} = State) -> case Event of {error, _GL, {Pid, Fmt, Args}} -> - case Fmt of - "** Generic server "++_ -> + FormatRaw = State#state.raw, + case {FormatRaw, Fmt} of + {false, "** Generic server "++_} -> %% gen_server terminate [Name, _Msg, _State, Reason] = Args, ?CRASH_LOG(Event), - ?LOGFMT(error, Pid, "gen_server ~w terminated with reason: ~s", + ?LOGFMT(Sink, error, Pid, "gen_server ~w terminated with reason: ~s", [Name, format_reason(Reason)]); - "** State machine "++_ -> + {false, "** State machine "++_} -> %% gen_fsm terminate [Name, _Msg, StateName, _StateData, Reason] = Args, ?CRASH_LOG(Event), - ?LOGFMT(error, Pid, "gen_fsm ~w in state ~w terminated with reason: ~s", + ?LOGFMT(Sink, error, Pid, "gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, format_reason(Reason)]); - "** gen_event handler"++_ -> + {false, "** gen_event handler"++_} -> %% gen_event handler terminate [ID, Name, _Msg, _State, Reason] = Args, ?CRASH_LOG(Event), - ?LOGFMT(error, Pid, "gen_event ~w installed in ~w terminated with reason: ~s", + ?LOGFMT(Sink, error, Pid, "gen_event ~w installed in ~w terminated with reason: ~s", [ID, Name, format_reason(Reason)]); - "** Cowboy handler"++_ -> + {false, "** Cowboy handler"++_} -> %% Cowboy HTTP server error ?CRASH_LOG(Event), case Args of [Module, Function, Arity, _Request, _State] -> %% we only get the 5-element list when its a non-exported function - ?LOGFMT(error, Pid, + ?LOGFMT(Sink, error, Pid, "Cowboy handler ~p terminated with reason: call to undefined function ~p:~p/~p", [Module, Module, Function, Arity]); [Module, Function, Arity, _Class, Reason | Tail] -> %% any other cowboy error_format list *always* ends with the stacktrace StackTrace = lists:last(Tail), - ?LOGFMT(error, Pid, + ?LOGFMT(Sink, error, Pid, "Cowboy handler ~p terminated in ~p:~p/~p with reason: ~s", [Module, Module, Function, Arity, format_reason({Reason, StackTrace})]) end; - "Ranch listener "++_ -> + {false, "Ranch listener "++_} -> %% Ranch errors ?CRASH_LOG(Event), case Args of [Ref, _Protocol, Worker, {[{reason, Reason}, {mfa, {Module, Function, Arity}}, {stacktrace, StackTrace} | _], _}] -> - ?LOGFMT(error, Worker, + ?LOGFMT(Sink, error, Worker, "Ranch listener ~p terminated in ~p:~p/~p with reason: ~s", [Ref, Module, Function, Arity, format_reason({Reason, StackTrace})]); [Ref, _Protocol, Worker, Reason] -> - ?LOGFMT(error, Worker, + ?LOGFMT(Sink, error, Worker, "Ranch listener ~p terminated with reason: ~s", [Ref, format_reason(Reason)]) end; - "webmachine error"++_ -> + {false, "webmachine error"++_} -> %% Webmachine HTTP server error ?CRASH_LOG(Event), [Path, Error] = Args, @@ -179,34 +202,34 @@ _ -> Error end, - ?LOGFMT(error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]); + ?LOGFMT(Sink, error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]); _ -> ?CRASH_LOG(Event), - ?LOGFMT(error, Pid, Fmt, Args) + ?LOGFMT(Sink, error, Pid, Fmt, Args) end; {error_report, _GL, {Pid, std_error, D}} -> ?CRASH_LOG(Event), - ?LOGMSG(error, Pid, print_silly_list(D)); + ?LOGMSG(Sink, error, Pid, print_silly_list(D)); {error_report, _GL, {Pid, supervisor_report, D}} -> ?CRASH_LOG(Event), case lists:sort(D) of [{errorContext, Ctx}, {offender, Off}, {reason, Reason}, {supervisor, Name}] -> Offender = format_offender(Off), - ?LOGFMT(error, Pid, + ?LOGFMT(Sink, error, Pid, "Supervisor ~w had child ~s exit with reason ~s in context ~w", [supervisor_name(Name), Offender, format_reason(Reason), Ctx]); _ -> - ?LOGMSG(error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D)) + ?LOGMSG(Sink, error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D)) end; {error_report, _GL, {Pid, crash_report, [Self, Neighbours]}} -> ?CRASH_LOG(Event), - ?LOGMSG(error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours)); + ?LOGMSG(Sink, error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours)); {warning_msg, _GL, {Pid, Fmt, Args}} -> - ?LOGFMT(warning, Pid, Fmt, Args); + ?LOGFMT(Sink, warning, Pid, Fmt, Args); {warning_report, _GL, {Pid, std_warning, Report}} -> - ?LOGMSG(warning, Pid, print_silly_list(Report)); + ?LOGMSG(Sink, warning, Pid, print_silly_list(Report)); {info_msg, _GL, {Pid, Fmt, Args}} -> - ?LOGFMT(info, Pid, Fmt, Args); + ?LOGFMT(Sink, info, Pid, Fmt, Args); {info_report, _GL, {Pid, std_info, D}} when is_list(D) -> Details = lists:sort(D), case Details of @@ -215,14 +238,14 @@ {ok, true} when Reason == stopped -> ok; _ -> - ?LOGFMT(info, Pid, "Application ~w exited with reason: ~s", + ?LOGFMT(Sink, info, Pid, "Application ~w exited with reason: ~s", [App, format_reason(Reason)]) end; _ -> - ?LOGMSG(info, Pid, print_silly_list(D)) + ?LOGMSG(Sink, info, Pid, print_silly_list(D)) end; {info_report, _GL, {Pid, std_info, D}} -> - ?LOGFMT(info, Pid, "~w", [D]); + ?LOGFMT(Sink, info, Pid, "~w", [D]); {info_report, _GL, {P, progress, D}} -> Details = lists:sort(D), case Details of @@ -231,19 +254,19 @@ {ok, true} -> ok; _ -> - ?LOGFMT(info, P, "Application ~w started on node ~w", + ?LOGFMT(Sink, info, P, "Application ~w started on node ~w", [App, Node]) end; [{started, Started}, {supervisor, Name}] -> MFA = format_mfa(get_value(mfargs, Started)), Pid = get_value(pid, Started), - ?LOGFMT(debug, P, "Supervisor ~w started ~s at pid ~w", + ?LOGFMT(Sink, debug, P, "Supervisor ~w started ~s at pid ~w", [supervisor_name(Name), MFA, Pid]); _ -> - ?LOGMSG(info, P, "PROGRESS REPORT " ++ print_silly_list(D)) + ?LOGMSG(Sink, info, P, "PROGRESS REPORT " ++ print_silly_list(D)) end; _ -> - ?LOGFMT(warning, self(), "Unexpected error_logger event ~w", [Event]) + ?LOGFMT(Sink, warning, self(), "Unexpected error_logger event ~w", [Event]) end, {ok, State}. diff -Nru erlang-lager-3.0.1/src/lager_app.erl erlang-lager-3.1.0/src/lager_app.erl --- erlang-lager-3.0.1/src/lager_app.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_app.erl 2016-01-27 21:39:55.000000000 +0000 @@ -188,6 +188,16 @@ lists:foreach(fun({Sink, Proplist}) -> configure_sink(Sink, Proplist) end, Sinks). +%% R15 doesn't know about application:get_env/3 +get_env(Application, Key, Default) -> + get_env_default(application:get_env(Application, Key), + Default). + +get_env_default(undefined, Default) -> + Default; +get_env_default({ok, Value}, _Default) -> + Value. + start(_StartType, _StartArgs) -> {ok, Pid} = lager_sup:start_link(), @@ -196,9 +206,8 @@ application:get_env(lager, async_threshold), application:get_env(lager, async_threshold_window)), start_handlers(?DEFAULT_SINK, - application:get_env(lager, handlers, ?DEFAULT_HANDLER_CONF)), + get_env(lager, handlers, ?DEFAULT_HANDLER_CONF)), - ok = add_configured_traces(), lager:update_loglevel_config(?DEFAULT_SINK), @@ -211,7 +220,9 @@ _ = lager_util:trace_filter(none), %% Now handle extra sinks - configure_extra_sinks(application:get_env(lager, extra_sinks, [])), + configure_extra_sinks(get_env(lager, extra_sinks, [])), + + ok = add_configured_traces(), clean_up_config_checks(), @@ -255,7 +266,7 @@ %% Allow the backend to generate a gen_event handler id, if it wants to. %% We don't use erlang:function_exported here because that requires the module %% already be loaded, which is unlikely at this phase of startup. Using code:load - %% caused undesireable side-effects with generating code-coverage reports. + %% caused undesirable side-effects with generating code-coverage reports. try Mod:config_to_id(Config) of Id -> {Id, Config} diff -Nru erlang-lager-3.0.1/src/lager.app.src erlang-lager-3.1.0/src/lager.app.src --- erlang-lager-3.0.1/src/lager.app.src 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager.app.src 2016-01-27 21:39:55.000000000 +0000 @@ -3,7 +3,7 @@ {application, lager, [ {description, "Erlang logging framework"}, - {vsn, "3.0.1"}, + {vsn, "3.1.0"}, {modules, []}, {applications, [ kernel, diff -Nru erlang-lager-3.0.1/src/lager_default_formatter.erl erlang-lager-3.1.0/src/lager_default_formatter.erl --- erlang-lager-3.0.1/src/lager_default_formatter.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_default_formatter.erl 2016-01-27 21:39:55.000000000 +0000 @@ -86,9 +86,18 @@ T; output(severity,Msg) -> atom_to_list(lager_msg:severity(Msg)); +output(blank,_Msg) -> + output({blank," "},_Msg); +output({blank,Fill},_Msg) -> + Fill; output(sev,Msg) -> %% Write brief acronym for the severity level (e.g. debug -> $D) [lager_util:level_to_chr(lager_msg:severity(Msg))]; +output(metadata, Msg) -> + output({metadata, "=", " "}, Msg); +output({metadata, IntSep, FieldSep}, Msg) -> + MD = lists:keysort(1, lager_msg:metadata(Msg)), + string:join([io_lib:format("~s~s~p", [K, IntSep, V]) || {K, V} <- MD], FieldSep); output(Prop,Msg) when is_atom(Prop) -> Metadata = lager_msg:metadata(Msg), make_printable(get_metadata(Prop,Metadata,<<"Undefined">>)); @@ -104,8 +113,47 @@ _ -> [ output(V, Msg) || V <- Present] end; +output({Prop, Present, Absent, Width}, Msg) when is_atom(Prop) -> + %% sort of like a poor man's ternary operator + Metadata = lager_msg:metadata(Msg), + case get_metadata(Prop, Metadata) of + undefined -> + [ output(V, Msg, Width) || V <- Absent]; + _ -> + [ output(V, Msg, Width) || V <- Present] + end; output(Other,_) -> make_printable(Other). +output(message, Msg, _Width) -> lager_msg:message(Msg); +output(date,Msg, _Width) -> + {D, _T} = lager_msg:datetime(Msg), + D; +output(time, Msg, _Width) -> + {_D, T} = lager_msg:datetime(Msg), + T; +output(severity, Msg, Width) -> + make_printable(atom_to_list(lager_msg:severity(Msg)), Width); +output(sev,Msg, _Width) -> + %% Write brief acronym for the severity level (e.g. debug -> $D) + [lager_util:level_to_chr(lager_msg:severity(Msg))]; +output(blank,_Msg, _Width) -> + output({blank, " "},_Msg, _Width); +output({blank, Fill},_Msg, _Width) -> + Fill; +output(metadata, Msg, _Width) -> + output({metadata, "=", " "}, Msg, _Width); +output({metadata, IntSep, FieldSep}, Msg, _Width) -> + MD = lists:keysort(1, lager_msg:metadata(Msg)), + [string:join([io_lib:format("~s~s~p", [K, IntSep, V]) || {K, V} <- MD], FieldSep)]; + +output(Prop, Msg, Width) when is_atom(Prop) -> + Metadata = lager_msg:metadata(Msg), + make_printable(get_metadata(Prop,Metadata,<<"Undefined">>), Width); +output({Prop,Default},Msg, Width) when is_atom(Prop) -> + Metadata = lager_msg:metadata(Msg), + make_printable(get_metadata(Prop,Metadata,output(Default,Msg)), Width); +output(Other,_, Width) -> make_printable(Other, Width). + output_color(_Msg,[]) -> []; output_color(Msg,Colors) -> Level = lager_msg:severity(Msg), @@ -120,6 +168,21 @@ make_printable(L) when is_list(L) orelse is_binary(L) -> L; make_printable(Other) -> io_lib:format("~p",[Other]). +make_printable(A,W) when is_integer(W)-> string:left(make_printable(A),W); +make_printable(A,{Align,W}) when is_integer(W) -> + case Align of + left -> + string:left(make_printable(A),W); + centre -> + string:centre(make_printable(A),W); + right -> + string:right(make_printable(A),W); + _ -> + string:left(make_printable(A),W) + end; + +make_printable(A,_W) -> make_printable(A). + get_metadata(Key, Metadata) -> get_metadata(Key, Metadata, undefined). @@ -167,7 +230,7 @@ [date, " ", time," [",severity,"] ",pid, " ", message, "\n"] ))) }, - {"Non existant metadata can default to string", + {"Non existent metadata can default to string", ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]), iolist_to_binary(format(lager_msg:new("Message", Now, @@ -177,7 +240,7 @@ [date, " ", time," [",severity,"] ",{does_not_exist,"Fallback"}, " ", message, "\n"] ))) }, - {"Non existant metadata can default to other metadata", + {"Non existent metadata can default to other metadata", ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]), iolist_to_binary(format(lager_msg:new("Message", Now, @@ -187,7 +250,7 @@ [date, " ", time," [",severity,"] ",{does_not_exist,pid}, " ", message, "\n"] ))) }, - {"Non existant metadata can default to a string2", + {"Non existent metadata can default to a string2", ?_assertEqual(iolist_to_binary(["Unknown Pid"]), iolist_to_binary(format(lager_msg:new("Message", Now, @@ -236,7 +299,95 @@ []), [{server,{pid, ["(", pid, ")"], ["(Unknown Server)"]}}] ))) + }, + {"Metadata can be printed in its enterity", + ?_assertEqual(iolist_to_binary(["bar=2 baz=3 foo=1"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{foo, 1}, {bar, 2}, {baz, 3}], + []), + [metadata] + ))) + }, + {"Metadata can be printed in its enterity with custom seperators", + ?_assertEqual(iolist_to_binary(["bar->2, baz->3, foo->1"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{foo, 1}, {bar, 2}, {baz, 3}], + []), + [{metadata, "->", ", "}] + ))) + }, + {"Metadata can have extra formatting with width 1", + ?_assertEqual(iolist_to_binary(["(hello )(hello )(hello)(hello)(hello)"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello}], + []), + ["(",{pid, [pid], "", 10},")", + "(",{pid, [pid], "", {bad_align,10}},")", + "(",{pid, [pid], "", bad10},")", + "(",{pid, [pid], "", {right,bad20}},")", + "(",{pid, [pid], "", {bad_align,bad20}},")"] + ))) + }, + {"Metadata can have extra formatting with width 2", + ?_assertEqual(iolist_to_binary(["(hello )"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello}], + []), + ["(",{pid, [pid], "", {left,10}},")"] + ))) + }, + {"Metadata can have extra formatting with width 3", + ?_assertEqual(iolist_to_binary(["( hello)"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello}], + []), + ["(",{pid, [pid], "", {right,10}},")"] + ))) + }, + {"Metadata can have extra formatting with width 4", + ?_assertEqual(iolist_to_binary(["( hello )"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello}], + []), + ["(",{pid, [pid], "", {centre,10}},")"] + ))) + }, + {"Metadata can have extra formatting with width 5", + ?_assertEqual(iolist_to_binary(["error |hello ! ( hello )"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello}], + []), + [{x,"",[severity,{blank,"|"},pid], 10},"!",blank,"(",{pid, [pid], "", {centre,10}},")"] + ))) + }, + {"Metadata can have extra formatting with width 6", + ?_assertEqual(iolist_to_binary([Time,Date," bar=2 baz=3 foo=1 pid=hello EMessage"]), + iolist_to_binary(format(lager_msg:new("Message", + Now, + error, + [{pid, hello},{foo, 1}, {bar, 2}, {baz, 3}], + []), + [{x,"",[time]}, {x,"",[date],20},blank,{x,"",[metadata],30},blank,{x,"",[sev],10},message, {message,message,"", {right,20}}] + ))) } + + + + ]. -endif. diff -Nru erlang-lager-3.0.1/src/lager.erl erlang-lager-3.1.0/src/lager.erl --- erlang-lager-3.0.1/src/lager.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager.erl 2016-01-27 21:39:55.000000000 +0000 @@ -22,18 +22,20 @@ -define(LAGER_MD_KEY, '__lager_metadata'). -define(TRACE_SINK, '__trace_sink'). +-define(ROTATE_TIMEOUT, 100000). %% API -export([start/0, log/3, log/4, log/5, log_unsafe/4, md/0, md/1, + rotate_handler/1, rotate_handler/2, rotate_sink/1, rotate_all/0, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, list_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, 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]). + do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -274,7 +276,16 @@ stop_trace({Backend, Filter, Level}) -> stop_trace(Backend, Filter, Level). -stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> +%% Important: validate_trace_filters orders the arguments of +%% trace tuples differently than the way outside callers have +%% the trace tuple. +%% +%% That is to say, outside they are represented as +%% `{Backend, Filter, Level}' +%% +%% and when they come back from validation, they're +%% `{Filter, Level, Backend}' +stop_trace_int({_Filter, _Level, Backend} = Trace, Sink) -> {Level, Traces} = lager_config:get({Sink, loglevel}), NewTraces = lists:delete(Trace, Traces), _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces ]), @@ -285,7 +296,10 @@ %% check no other traces point here case lists:keyfind(Backend, 3, NewTraces) of false -> - gen_event:delete_handler(Sink, Backend, []); + gen_event:delete_handler(Sink, Backend, []), + lager_config:global_set(handlers, + lists:keydelete(Backend, 1, + lager_config:global_get(handlers))); _ -> ok end; @@ -580,3 +594,45 @@ end end. + +%% @doc Print stacktrace in human readable form +pr_stacktrace(Stacktrace) -> + Indent = "\n ", + lists:foldl( + fun(Entry, Acc) -> + Acc ++ Indent ++ error_logger_lager_h:format_mfa(Entry) + end, + [], + lists:reverse(Stacktrace)). + +pr_stacktrace(Stacktrace, {Class, Reason}) -> + lists:flatten( + pr_stacktrace(Stacktrace) ++ "\n" ++ io_lib:format("~s:~p", [Class, Reason])). + +rotate_sink(Sink) -> + Handlers = lager_config:global_get(handlers), + RotateHandlers = lists:filtermap( + fun({Handler,_,S}) when S == Sink -> {true, {Handler, Sink}}; + (_) -> false + end, + Handlers), + rotate_handlers(RotateHandlers). + +rotate_all() -> + rotate_handlers(lists:map(fun({H,_,S}) -> {H, S} end, + lager_config:global_get(handlers))). + + +rotate_handlers(Handlers) -> + [ rotate_handler(Handler, Sink) || {Handler, Sink} <- Handlers ]. + + +rotate_handler(Handler) -> + Handlers = lager_config:global_get(handlers), + case lists:keyfind(Handler, 1, Handlers) of + {Handler, _, Sink} -> rotate_handler(Handler, Sink); + false -> ok + end. + +rotate_handler(Handler, Sink) -> + gen_event:call(Sink, Handler, rotate, ?ROTATE_TIMEOUT). diff -Nru erlang-lager-3.0.1/src/lager_file_backend.erl erlang-lager-3.1.0/src/lager_file_backend.erl --- erlang-lager-3.0.1/src/lager_file_backend.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_file_backend.erl 2016-01-27 21:39:55.000000000 +0000 @@ -83,19 +83,19 @@ -spec init([option(),...]) -> {ok, #state{}} | {error, bad_config}. init({FileName, LogLevel}) when is_list(FileName), is_atom(LogLevel) -> - %% backwards compatability hack + %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}]); init({FileName, LogLevel, Size, Date, Count}) when is_list(FileName), is_atom(LogLevel) -> - %% backwards compatability hack + %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {size, Size}, {date, Date}, {count, Count}]); init([{FileName, LogLevel, Size, Date, Count}, {Formatter,FormatterConfig}]) when is_list(FileName), is_atom(LogLevel), is_atom(Formatter) -> - %% backwards compatability hack + %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {size, Size}, {date, Date}, {count, Count}, {formatter, Formatter}, {formatter_config, FormatterConfig}]); init([LogFile,{Formatter}]) -> - %% backwards compatability hack + %% backwards compatibility hack init([LogFile,{Formatter,[]}]); init([{FileName, LogLevel}, {Formatter,FormatterConfig}]) when is_list(FileName), is_atom(LogLevel), is_atom(Formatter) -> - %% backwards compatability hack + %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {formatter, Formatter}, {formatter_config, FormatterConfig}]); init(LogFileConfig) when is_list(LogFileConfig) -> case validate_logfile_proplist(LogFileConfig) of @@ -142,6 +142,9 @@ ?INT_LOG(notice, "Changed loghwm of ~s to ~p", [Name, Hwm]), {ok, {last_loghwm, Shaper#lager_shaper.hwm}, State#state{shaper=NewShaper}} end; +handle_call(rotate, State = #state{name=File}) -> + {ok, NewState} = handle_info({rotate, File}, State), + {ok, ok, NewState}; handle_call(_Request, State) -> {ok, ok, State}. @@ -178,16 +181,16 @@ %% @private handle_info({rotate, File}, #state{name=File,count=Count,date=Date} = State) -> _ = lager_util:rotate_logfile(File, Count), + State1 = close_file(State), schedule_rotation(File, Date), - {ok, State}; + {ok, State1}; handle_info(_Info, State) -> {ok, State}. %% @private -terminate(_Reason, #state{fd=FD}) -> - %% flush and close any file handles - _ = file:datasync(FD), - _ = file:close(FD), +terminate(_Reason, State) -> + %% leaving this function call unmatched makes dialyzer cranky + _ = close_file(State), ok. %% @private @@ -401,6 +404,14 @@ erlang:send_after(lager_util:calculate_next_rotation(Date) * 1000, self(), {rotate, Name}), ok. +close_file(#state{fd=undefined} = State) -> + State; +close_file(#state{fd=FD} = State) -> + %% Flush and close any file handles. + _ = file:datasync(FD), + _ = file:close(FD), + State#state{fd=undefined}. + -ifdef(TEST). get_loglevel_test() -> @@ -629,6 +640,16 @@ ?assert(filelib:is_regular("test.log.0")) end }, + {"rotation call should work", + fun() -> + gen_event:add_handler(lager_event, {lager_file_backend, "test.log"}, [{file, "test.log"}, {level, info}, {check_interval, 1000}]), + lager:log(error, self(), "Test message1"), + lager:log(error, self(), "Test message1"), + gen_event:call(lager_event, {lager_file_backend, "test.log"}, rotate, infinity), + lager:log(error, self(), "Test message1"), + ?assert(filelib:is_regular("test.log.0")) + end + }, {"sync_on option should work", fun() -> gen_event:add_handler(lager_event, lager_file_backend, [{file, "test.log"}, {level, info}, {sync_on, "=info"}, {check_interval, 5000}, {sync_interval, 5000}]), diff -Nru erlang-lager-3.0.1/src/lager_stdlib.erl erlang-lager-3.1.0/src/lager_stdlib.erl --- erlang-lager-3.0.1/src/lager_stdlib.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_stdlib.erl 2016-01-27 21:39:55.000000000 +0000 @@ -39,7 +39,7 @@ string_p(Term) -> string_p1(Term). -string_p1([H|T]) when is_integer(H), H >= $\s, H < 255 -> +string_p1([H|T]) when is_integer(H), H >= $\s, H < 256 -> string_p1(T); string_p1([$\n|T]) -> string_p1(T); string_p1([$\r|T]) -> string_p1(T); diff -Nru erlang-lager-3.0.1/src/lager_transform.erl erlang-lager-3.1.0/src/lager_transform.erl --- erlang-lager-3.0.1/src/lager_transform.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_transform.erl 2016-01-27 21:39:55.000000000 +0000 @@ -172,7 +172,7 @@ [Attrs, Format, Args] -> {concat_lists(Attrs, DefaultAttrs), Format, Args} end, - %% Generate some unique variable names so we don't accidentaly export from case clauses. + %% Generate some unique variable names so we don't accidentally export from case clauses. %% Note that these are not actual atoms, but the AST treats variable names as atoms. LevelVar = make_varname("__Level", Line), TracesVar = make_varname("__Traces", Line), diff -Nru erlang-lager-3.0.1/src/lager_util.erl erlang-lager-3.1.0/src/lager_util.erl --- erlang-lager-3.0.1/src/lager_util.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/src/lager_util.erl 2016-01-27 21:39:55.000000000 +0000 @@ -482,7 +482,14 @@ expand_path(RelPath) -> case application:get_env(lager, log_root) of {ok, LogRoot} when is_list(LogRoot) -> % Join relative path - filename:join(LogRoot, RelPath); + %% check if the given RelPath contains LogRoot, if so, do not add + %% it again; see gh #304 + case string:str(filename:dirname(RelPath), LogRoot) of + X when X > 0 -> + RelPath; + _Zero -> + filename:join(LogRoot, RelPath) + end; undefined -> % No log_root given, keep relative path RelPath end. @@ -782,6 +789,7 @@ ok = application:set_env(lager, log_root, "log/dir"), ?assertEqual("/foo/bar", expand_path("/foo/bar")), % Absolute path should not be changed ?assertEqual("log/dir/foo/bar", expand_path("foo/bar")), + ?assertEqual("log/dir/foo/bar", expand_path("log/dir/foo/bar")), %% gh #304 case OldRootVal of undefined -> application:unset_env(lager, log_root); diff -Nru erlang-lager-3.0.1/test/lager_rotate.erl erlang-lager-3.1.0/test/lager_rotate.erl --- erlang-lager-3.0.1/test/lager_rotate.erl 1970-01-01 00:00:00.000000000 +0000 +++ erlang-lager-3.1.0/test/lager_rotate.erl 2016-01-27 21:39:55.000000000 +0000 @@ -0,0 +1,138 @@ +-module(lager_rotate). + +-compile(export_all). + +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. + + +rotate_test_() -> + {foreach, + fun() -> + file:write_file("test1.log", ""), + file:write_file("test2.log", ""), + file:write_file("test3.log", ""), + file:delete("test1.log.0"), + file:delete("test2.log.0"), + file:delete("test3.log.0"), + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, + [{lager_file_backend, [{file, "test1.log"}, {level, info}]}, + {lager_file_backend, [{file, "test2.log"}, {level, info}]}]), + application:set_env(lager, extra_sinks, + [{sink_event, + [{handlers, + [{lager_file_backend, [{file, "test3.log"}, {level, info}]}]} + ]}]), + application:set_env(lager, error_logger_redirect, false), + application:set_env(lager, async_threshold, undefined), + lager:start() + end, + fun(_) -> + file:delete("test1.log"), + file:delete("test2.log"), + file:delete("test3.log"), + file:delete("test1.log.0"), + file:delete("test2.log.0"), + file:delete("test3.log.0"), + application:stop(lager), + application:stop(goldrush), + error_logger:tty(true) + end, + [{"Rotate single file", + fun() -> + lager:log(error, self(), "Test message 1"), + lager:log(sink_event, error, self(), "Sink test message 1", []), + lager:rotate_handler({lager_file_backend, "test1.log"}), + timer:sleep(1000), + true = filelib:is_regular("test1.log.0"), + lager:log(error, self(), "Test message 2"), + lager:log(sink_event, error, self(), "Sink test message 2", []), + + {ok, File1} = file:read_file("test1.log"), + {ok, File2} = file:read_file("test2.log"), + {ok, SinkFile} = file:read_file("test3.log"), + {ok, File1Old} = file:read_file("test1.log.0"), + + have_no_log(File1, <<"Test message 1">>), + have_log(File1, <<"Test message 2">>), + + have_log(File2, <<"Test message 1">>), + have_log(File2, <<"Test message 2">>), + + have_log(File1Old, <<"Test message 1">>), + have_no_log(File1Old, <<"Test message 2">>), + + have_log(SinkFile, <<"Sink test message 1">>), + have_log(SinkFile, <<"Sink test message 2">>) + end}, + {"Rotate sink", + fun() -> + lager:log(error, self(), "Test message 1"), + lager:log(sink_event, error, self(), "Sink test message 1", []), + lager:rotate_sink(sink_event), + timer:sleep(1000), + true = filelib:is_regular("test3.log.0"), + lager:log(error, self(), "Test message 2"), + lager:log(sink_event, error, self(), "Sink test message 2", []), + {ok, File1} = file:read_file("test1.log"), + {ok, File2} = file:read_file("test2.log"), + {ok, SinkFile} = file:read_file("test3.log"), + {ok, SinkFileOld} = file:read_file("test3.log.0"), + + have_log(File1, <<"Test message 1">>), + have_log(File1, <<"Test message 2">>), + + have_log(File2, <<"Test message 1">>), + have_log(File2, <<"Test message 2">>), + + have_log(SinkFileOld, <<"Sink test message 1">>), + have_no_log(SinkFileOld, <<"Sink test message 2">>), + + have_no_log(SinkFile, <<"Sink test message 1">>), + have_log(SinkFile, <<"Sink test message 2">>) + end}, + {"Rotate all", + fun() -> + lager:log(error, self(), "Test message 1"), + lager:log(sink_event, error, self(), "Sink test message 1", []), + lager:rotate_all(), + timer:sleep(1000), + true = filelib:is_regular("test3.log.0"), + lager:log(error, self(), "Test message 2"), + lager:log(sink_event, error, self(), "Sink test message 2", []), + {ok, File1} = file:read_file("test1.log"), + {ok, File2} = file:read_file("test2.log"), + {ok, SinkFile} = file:read_file("test3.log"), + {ok, File1Old} = file:read_file("test1.log.0"), + {ok, File2Old} = file:read_file("test2.log.0"), + {ok, SinkFileOld} = file:read_file("test3.log.0"), + + have_no_log(File1, <<"Test message 1">>), + have_log(File1, <<"Test message 2">>), + + have_no_log(File2, <<"Test message 1">>), + have_log(File2, <<"Test message 2">>), + + have_no_log(SinkFile, <<"Sink test message 1">>), + have_log(SinkFile, <<"Sink test message 2">>), + + have_log(SinkFileOld, <<"Sink test message 1">>), + have_no_log(SinkFileOld, <<"Sink test message 2">>), + + have_log(File1Old, <<"Test message 1">>), + have_no_log(File1Old, <<"Test message 2">>), + + have_log(File2Old, <<"Test message 1">>), + have_no_log(File2Old, <<"Test message 2">>) + + end}]}. + +have_log(Data, Log) -> + {_,_} = binary:match(Data, Log). + +have_no_log(Data, Log) -> + nomatch = binary:match(Data, Log). + diff -Nru erlang-lager-3.0.1/test/lager_test_backend.erl erlang-lager-3.1.0/test/lager_test_backend.erl --- erlang-lager-3.0.1/test/lager_test_backend.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/test/lager_test_backend.erl 2016-01-27 21:39:55.000000000 +0000 @@ -536,6 +536,39 @@ ok end }, + {"stopped trace stops and removes its event handler - default sink (gh#267)", + fun() -> + Sink = ?DEFAULT_SINK, + StartHandlers = gen_event:which_handlers(Sink), + {_, T0} = lager_config:get({Sink, loglevel}), + StartGlobal = lager_config:global_get(handlers), + ?assertEqual([], T0), + {ok, TestTrace1} = lager:trace_file("/tmp/test", [{a,b}]), + MidHandlers = gen_event:which_handlers(Sink), + {ok, TestTrace2} = lager:trace_file("/tmp/test", [{c,d}]), + MidHandlers = gen_event:which_handlers(Sink), + ?assertEqual(length(StartHandlers)+1, length(MidHandlers)), + MidGlobal = lager_config:global_get(handlers), + ?assertEqual(length(StartGlobal)+1, length(MidGlobal)), + {_, T1} = lager_config:get({Sink, loglevel}), + ?assertEqual(2, length(T1)), + ok = lager:stop_trace(TestTrace1), + {_, T2} = lager_config:get({Sink, loglevel}), + ?assertEqual(1, length(T2)), + ?assertEqual(length(StartHandlers)+1, length( + gen_event:which_handlers(Sink))), + + ?assertEqual(length(StartGlobal)+1, length(lager_config:global_get(handlers))), + ok = lager:stop_trace(TestTrace2), + EndHandlers = gen_event:which_handlers(?DEFAULT_SINK), + EndGlobal = lager_config:global_get(handlers), + {_, T3} = lager_config:get({Sink, loglevel}), + ?assertEqual([], T3), + ?assertEqual(StartHandlers, EndHandlers), + ?assertEqual(StartGlobal, EndGlobal), + ok + end + }, {"record printing works", fun() -> print_state(), @@ -691,6 +724,39 @@ ok end }, + {"stopped trace stops and removes its event handler - test sink (gh#267)", + fun() -> + Sink = ?TEST_SINK_EVENT, + StartHandlers = gen_event:which_handlers(Sink), + {_, T0} = lager_config:get({Sink, loglevel}), + StartGlobal = lager_config:global_get(handlers), + ?assertEqual([], T0), + {ok, TestTrace1} = lager:trace_file("/tmp/test", [{sink, Sink}, {a,b}]), + MidHandlers = gen_event:which_handlers(Sink), + {ok, TestTrace2} = lager:trace_file("/tmp/test", [{sink, Sink}, {c,d}]), + MidHandlers = gen_event:which_handlers(Sink), + ?assertEqual(length(StartHandlers)+1, length(MidHandlers)), + MidGlobal = lager_config:global_get(handlers), + ?assertEqual(length(StartGlobal)+1, length(MidGlobal)), + {_, T1} = lager_config:get({Sink, loglevel}), + ?assertEqual(2, length(T1)), + ok = lager:stop_trace(TestTrace1), + {_, T2} = lager_config:get({Sink, loglevel}), + ?assertEqual(1, length(T2)), + ?assertEqual(length(StartHandlers)+1, length( + gen_event:which_handlers(Sink))), + + ?assertEqual(length(StartGlobal)+1, length(lager_config:global_get(handlers))), + ok = lager:stop_trace(TestTrace2), + EndHandlers = gen_event:which_handlers(Sink), + EndGlobal = lager_config:global_get(handlers), + {_, T3} = lager_config:get({Sink, loglevel}), + ?assertEqual([], T3), + ?assertEqual(StartHandlers, EndHandlers), + ?assertEqual(StartGlobal, EndGlobal), + ok + end + }, {"log messages below the threshold are ignored", fun() -> ?assertEqual(0, count(?TEST_SINK_EVENT)), @@ -785,90 +851,132 @@ ?assertEqual(Expected, Actual) end. +error_logger_redirect_crash_setup() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, error_logger_redirect, true), + application:set_env(lager, handlers, [{?MODULE, error}]), + lager:start(), + crash:start(), + lager_event. + +error_logger_redirect_crash_setup_sink() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, error_logger_redirect, true), + application:unset_env(lager, handlers), + application:set_env(lager, extra_sinks, [ + {error_logger_lager_event, [ + {handlers, [{?MODULE, error}]}]}]), + lager:start(), + crash:start(), + error_logger_lager_event. + +error_logger_redirect_crash_cleanup(_Sink) -> + application:stop(lager), + application:stop(goldrush), + application:unset_env(lager, extra_sinks), + case whereis(crash) of + undefined -> ok; + Pid -> exit(Pid, kill) + end, + error_logger:tty(true). error_logger_redirect_crash_test_() -> - TestBody=fun(Name,CrashReason,Expected) -> {Name, + TestBody=fun(Name,CrashReason,Expected) -> + fun(Sink) -> + {Name, fun() -> Pid = whereis(crash), crash(CrashReason), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), test_body(Expected, lists:flatten(Msg)), ?assertEqual(Pid,proplists:get_value(pid,Metadata)), ?assertEqual(lager_util:level_to_num(error),Level) end } + end end, - {foreach, - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, error_logger_redirect, true), - application:set_env(lager, handlers, [{?MODULE, error}]), - lager:start(), - crash:start() - end, - - fun(_) -> - application:stop(lager), - application:stop(goldrush), - case whereis(crash) of - undefined -> ok; - Pid -> exit(Pid, kill) - end, - error_logger:tty(true) - end, - [ + Tests = [ + fun(Sink) -> {"again, there is nothing up my sleeve", fun() -> - ?assertEqual(undefined, pop()), - ?assertEqual(0, count()) + ?assertEqual(undefined, pop(Sink)), + ?assertEqual(0, count(Sink)) end - }, + } + end, - TestBody("bad return value",bad_return,"gen_server crash terminated with reason: bad return value: bleh"), - TestBody("bad return value with string",bad_return_string,"gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}"), - TestBody("bad return uncaught throw",throw,"gen_server crash terminated with reason: bad return value: a_ball"), - TestBody("case clause",case_clause,"gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3"), - TestBody("case clause string",case_clause_string,"gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3"), - TestBody("function clause",function_clause,"gen_server crash terminated with reason: no function clause matching crash:function({})"), - TestBody("if clause",if_clause,"gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3"), - TestBody("try clause",try_clause,"gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3"), - TestBody("undefined function",undef,"gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3"), - TestBody("bad math",badarith,"gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3"), - TestBody("bad match",badmatch,"gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3"), - TestBody("bad arity",badarity,"gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3"), - TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"), - TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"), - TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"), - TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"), - TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3") - ] - }. + TestBody("bad return value",bad_return,"gen_server crash terminated with reason: bad return value: bleh"), + TestBody("bad return value with string",bad_return_string,"gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}"), + TestBody("bad return uncaught throw",throw,"gen_server crash terminated with reason: bad return value: a_ball"), + TestBody("case clause",case_clause,"gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3"), + TestBody("case clause string",case_clause_string,"gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3"), + TestBody("function clause",function_clause,"gen_server crash terminated with reason: no function clause matching crash:function({})"), + TestBody("if clause",if_clause,"gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3"), + TestBody("try clause",try_clause,"gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3"), + TestBody("undefined function",undef,"gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3"), + TestBody("bad math",badarith,"gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3"), + TestBody("bad match",badmatch,"gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3"), + TestBody("bad arity",badarity,"gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3"), + TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"), + TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"), + TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"), + TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"), + TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3") + ], + {"Error logger redirect crash", [ + {"Redirect to default sink", + {foreach, + fun error_logger_redirect_crash_setup/0, + fun error_logger_redirect_crash_cleanup/1, + Tests}}, + {"Redirect to error_logger_lager_event sink", + {foreach, + fun error_logger_redirect_crash_setup_sink/0, + fun error_logger_redirect_crash_cleanup/1, + Tests}} + ]}. -error_logger_redirect_test_() -> - {foreach, - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, error_logger_redirect, true), - application:set_env(lager, handlers, [{?MODULE, info}]), - lager:start(), - lager:log(error, self(), "flush flush"), - timer:sleep(100), - gen_event:call(lager_event, ?MODULE, flush) - end, - fun(_) -> - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end, - [ +error_logger_redirect_setup() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, error_logger_redirect, true), + application:set_env(lager, handlers, [{?MODULE, info}]), + lager:start(), + lager:log(error, self(), "flush flush"), + timer:sleep(100), + gen_event:call(lager_event, ?MODULE, flush), + lager_event. + +error_logger_redirect_setup_sink() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, error_logger_redirect, true), + application:unset_env(lager, handlers), + application:set_env(lager, extra_sinks, [ + {error_logger_lager_event, [ + {handlers, [{?MODULE, info}]}]}]), + lager:start(), + lager:log(error_logger_lager_event, error, self(), "flush flush", []), + timer:sleep(100), + gen_event:call(error_logger_lager_event, ?MODULE, flush), + error_logger_lager_event. + +error_logger_redirect_cleanup(_) -> + application:stop(lager), + application:stop(goldrush), + application:unset_env(lager, extra_sinks), + error_logger:tty(true). + +error_logger_redirect_test_() -> + Tests = [ {"error reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:error_report([{this, is}, a, {silly, format}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = "this: is, a, silly: format", @@ -877,10 +985,10 @@ end }, {"string error reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:error_report("this is less silly"), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = "this is less silly", @@ -888,10 +996,10 @@ end }, {"error messages are printed", - fun() -> + fun(Sink) -> sync_error_logger:error_msg("doom, doom has come upon you all"), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = "doom, doom has come upon you all", @@ -899,29 +1007,29 @@ end }, {"error messages with unicode characters in Args are printed", - fun() -> + fun(Sink) -> sync_error_logger:error_msg("~ts", ["Привет!"]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Привет!", lists:flatten(Msg)) end }, {"error messages are truncated at 4096 characters", - fun() -> + fun(Sink) -> sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg,_Metadata} = pop(), + {_, _, Msg,_Metadata} = pop(Sink), ?assert(length(lists:flatten(Msg)) < 5100) end }, {"info reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:info_report([{this, is}, a, {silly, format}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = "this: is, a, silly: format", @@ -929,101 +1037,101 @@ end }, {"info reports are truncated at 4096 characters", - fun() -> + fun(Sink) -> sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5000) end }, {"single term info reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:info_report({foolish, bees}), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"single term error reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:error_report({foolish, bees}), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"string info reports are printed", - fun() -> + fun(Sink) -> sync_error_logger:info_report("this is less silly"), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("this is less silly", lists:flatten(Msg)) end }, {"string info reports are truncated at 4096 characters", - fun() -> + fun(Sink) -> sync_error_logger:info_report(string:copies("this is less silly", 1000)), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5100) end }, {"strings in a mixed report are printed as strings", - fun() -> + fun(Sink) -> sync_error_logger:info_report(["this is less silly", {than, "this"}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("\"this is less silly\", than: \"this\"", lists:flatten(Msg)) end }, {"info messages are printed", - fun() -> + fun(Sink) -> sync_error_logger:info_msg("doom, doom has come upon you all"), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg)) end }, {"info messages are truncated at 4096 characters", - fun() -> + fun(Sink) -> sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5100) end }, {"info messages with unicode characters in Args are printed", - fun() -> + fun(Sink) -> sync_error_logger:info_msg("~ts", ["Привет!"]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Привет!", lists:flatten(Msg)) end }, {"warning messages with unicode characters in Args are printed", - fun() -> + fun(Sink) -> sync_error_logger:warning_msg("~ts", ["Привет!"]), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(Map),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Привет!", lists:flatten(Msg)) @@ -1031,63 +1139,63 @@ }, {"warning messages are printed at the correct level", - fun() -> + fun(Sink) -> sync_error_logger:warning_msg("doom, doom has come upon you all"), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(Map),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg)) end }, {"warning reports are printed at the correct level", - fun() -> + fun(Sink) -> sync_error_logger:warning_report([{i, like}, pie]), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(Map),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("i: like, pie", lists:flatten(Msg)) end }, {"single term warning reports are printed at the correct level", - fun() -> + fun(Sink) -> sync_error_logger:warning_report({foolish, bees}), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(Map),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"application stop reports", - fun() -> + fun(Sink) -> sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Application foo exited with reason: quittin_time", lists:flatten(Msg)) end }, {"supervisor reports", - fun() -> + fun(Sink) -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", lists:flatten(Msg)) end }, {"supervisor reports with real error", - fun() -> + fun(Sink) -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, {function_clause,[{crash,handle_info,[foo]}]}}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", lists:flatten(Msg)) @@ -1095,10 +1203,10 @@ }, {"supervisor reports with real error and pid", - fun() -> + fun(Sink) -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, {function_clause,[{crash,handle_info,[foo]}]}}, {supervisor, somepid}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor somepid had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", lists:flatten(Msg)) @@ -1106,20 +1214,20 @@ }, {"supervisor_bridge reports", - fun() -> + fun(Sink) -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", lists:flatten(Msg)) end }, {"application progress report", - fun() -> + fun(Sink) -> sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(info),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("Application foo started on node ~w", [node()])), @@ -1127,34 +1235,34 @@ end }, {"supervisor progress report", - fun() -> - lager:set_loglevel(?MODULE, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), + fun(Sink) -> + lager:set_loglevel(Sink, ?MODULE, undefined, debug), + ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(debug),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor foo started foo:bar/1 at pid baz", lists:flatten(Msg)) end }, {"supervisor progress report with pid", - fun() -> - lager:set_loglevel(?MODULE, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), + fun(Sink) -> + lager:set_loglevel(Sink, ?MODULE, undefined, debug), + ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), sync_error_logger:info_report(progress, [{supervisor, somepid}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(debug),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Supervisor somepid started foo:bar/1 at pid baz", lists:flatten(Msg)) end }, {"crash report for emfile", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, emfile, [{stack, trace, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self()])), @@ -1162,10 +1270,10 @@ end }, {"crash report for system process limit", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])), @@ -1173,10 +1281,10 @@ end }, {"crash report for system process limit2", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn_opt, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])), @@ -1184,10 +1292,10 @@ end }, {"crash report for system port limit", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, open_port, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self()])), @@ -1195,10 +1303,10 @@ end }, {"crash report for system port limit", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, list_to_atom, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: tried to create an atom larger than 255, or maximum atom count exceeded", [self()])), @@ -1206,10 +1314,10 @@ end }, {"crash report for system ets table limit", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, test}, {error_info, {error, system_limit, [{ets,new,[segment_offsets,[ordered_set,public]]},{mi_segment,open_write,1},{mi_buffer_converter,handle_cast,2},{gen_server,handle_msg,5},{proc_lib,init_p_do_apply,3}]}}], []]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [test])), @@ -1217,75 +1325,75 @@ end }, {"crash report for unknown system limit should be truncated at 500 characters", - fun() -> + fun(Sink) -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, system_limit, [{wtf,boom,[string:copies("aaaa", 4096)]}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg,_Metadata} = pop(), + {_, _, Msg,_Metadata} = pop(Sink), ?assert(length(lists:flatten(Msg)) > 550), ?assert(length(lists:flatten(Msg)) < 600) end }, {"crash reports for 'special processes' should be handled right - function_clause", - fun() -> + fun(Sink) -> {ok, Pid} = special_process:start(), unlink(Pid), Pid ! function_clause, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg, _Metadata} = pop(), + {_, _, Msg, _Metadata} = pop(Sink), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no function clause matching special_process:foo(bar)", [Pid])), test_body(Expected, lists:flatten(Msg)) end }, {"crash reports for 'special processes' should be handled right - case_clause", - fun() -> + fun(Sink) -> {ok, Pid} = special_process:start(), unlink(Pid), Pid ! {case_clause, wtf}, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg, _Metadata} = pop(), + {_, _, Msg, _Metadata} = pop(Sink), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no case clause matching wtf in special_process:loop/0", [Pid])), test_body(Expected, lists:flatten(Msg)) end }, {"crash reports for 'special processes' should be handled right - exit", - fun() -> + fun(Sink) -> {ok, Pid} = special_process:start(), unlink(Pid), Pid ! exit, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg, _Metadata} = pop(), + {_, _, Msg, _Metadata} = pop(Sink), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours exited with reason: byebye in special_process:loop/0", [Pid])), test_body(Expected, lists:flatten(Msg)) end }, {"crash reports for 'special processes' should be handled right - error", - fun() -> + fun(Sink) -> {ok, Pid} = special_process:start(), unlink(Pid), Pid ! error, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg, _Metadata} = pop(), + {_, _, Msg, _Metadata} = pop(Sink), Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: mybad in special_process:loop/0", [Pid])), test_body(Expected, lists:flatten(Msg)) end }, {"webmachine error reports", - fun() -> + fun(Sink) -> Path = "/cgi-bin/phpmyadmin", Reason = {error,{error,{badmatch,{error,timeout}}, [{myapp,dostuff,2,[{file,"src/myapp.erl"},{line,123}]}, {webmachine_resource,resource_call,3,[{file,"src/webmachine_resource.erl"},{line,169}]}]}}, sync_error_logger:error_msg("webmachine error: path=~p~n~p~n", [Path, Reason]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Webmachine error at path \"/cgi-bin/phpmyadmin\" : no match of right hand value {error,timeout} in myapp:dostuff/2 line 123", lists:flatten(Msg)) @@ -1293,7 +1401,7 @@ end }, {"Cowboy error reports, 8 arg version", - fun() -> + fun(Sink) -> Stack = [{my_handler,init, 3,[{file,"src/my_handler.erl"},{line,123}]}, {cowboy_handler,handler_init,4,[{file,"src/cowboy_handler.erl"},{line,169}]}], @@ -1306,14 +1414,14 @@ [my_handler, init, 3, error, {badmatch, {error, timeout}}, [], "Request", Stack]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Cowboy handler my_handler terminated in my_handler:init/3 with reason: no match of right hand value {error,timeout} in my_handler:init/3 line 123", lists:flatten(Msg)) end }, {"Cowboy error reports, 10 arg version", - fun() -> + fun(Sink) -> Stack = [{my_handler,somecallback, 3,[{file,"src/my_handler.erl"},{line,123}]}, {cowboy_handler,handler_init,4,[{file,"src/cowboy_handler.erl"},{line,169}]}], sync_error_logger:error_msg( @@ -1325,51 +1433,67 @@ {}, "Request", Stack]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Cowboy handler my_handler terminated in my_handler:somecallback/3 with reason: no match of right hand value {error,timeout} in my_handler:somecallback/3 line 123", lists:flatten(Msg)) end }, {"Cowboy error reports, 5 arg version", - fun() -> + fun(Sink) -> sync_error_logger:error_msg( "** Cowboy handler ~p terminating; " "function ~p/~p was not exported~n" "** Request was ~p~n** State was ~p~n~n", [my_handler, to_json, 2, "Request", {}]), _ = gen_event:which_handlers(error_logger), - {Level, _, Msg,Metadata} = pop(), + {Level, _, Msg,Metadata} = pop(Sink), ?assertEqual(lager_util:level_to_num(error),Level), ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assertEqual("Cowboy handler my_handler terminated with reason: call to undefined function my_handler:to_json/2", lists:flatten(Msg)) end }, {"messages should not be generated if they don't satisfy the threshold", - fun() -> - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), + fun(Sink) -> + lager:set_loglevel(Sink, ?MODULE, undefined, error), + ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), sync_error_logger:info_report([hello, world]), _ = gen_event:which_handlers(error_logger), - ?assertEqual(0, count()), - ?assertEqual(0, count_ignored()), - lager:set_loglevel(?MODULE, info), - ?assertEqual({?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), + ?assertEqual(0, count(Sink)), + ?assertEqual(0, count_ignored(Sink)), + lager:set_loglevel(Sink, ?MODULE, undefined, info), + ?assertEqual({?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), sync_error_logger:info_report([hello, world]), _ = gen_event:which_handlers(error_logger), - ?assertEqual(1, count()), - ?assertEqual(0, count_ignored()), - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(debug)), []}), + ?assertEqual(1, count(Sink)), + ?assertEqual(0, count_ignored(Sink)), + lager:set_loglevel(Sink, ?MODULE, undefined, error), + ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), + lager_config:set({Sink, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}), sync_error_logger:info_report([hello, world]), _ = gen_event:which_handlers(error_logger), - ?assertEqual(1, count()), - ?assertEqual(1, count_ignored()) + ?assertEqual(1, count(Sink)), + ?assertEqual(1, count_ignored(Sink)) end } - ] - }. + ], + SinkTests = lists:map( + fun({Name, F}) -> + fun(Sink) -> {Name, fun() -> F(Sink) end} end + end, + Tests), + {"Error logger redirect", [ + {"Redirect to default sink", + {foreach, + fun error_logger_redirect_setup/0, + fun error_logger_redirect_cleanup/1, + SinkTests}}, + {"Redirect to error_logger_lager_event sink", + {foreach, + fun error_logger_redirect_setup_sink/0, + fun error_logger_redirect_cleanup/1, + SinkTests}} + ]}. safe_format_test() -> ?assertEqual("foo bar", lists:flatten(lager:safe_format("~p ~p", [foo, bar], 1024))), diff -Nru erlang-lager-3.0.1/test/pr_stacktrace_test.erl erlang-lager-3.1.0/test/pr_stacktrace_test.erl --- erlang-lager-3.0.1/test/pr_stacktrace_test.erl 1970-01-01 00:00:00.000000000 +0000 +++ erlang-lager-3.1.0/test/pr_stacktrace_test.erl 2016-01-27 21:39:55.000000000 +0000 @@ -0,0 +1,55 @@ +-module(pr_stacktrace_test). + +-compile([{parse_transform, lager_transform}]). + +-include_lib("eunit/include/eunit.hrl"). + +make_throw() -> + throw({test, exception}). + +bad_arity() -> + lists:concat([], []). + +bad_arg() -> + integer_to_list(1.0). + +pr_stacktrace_throw_test() -> + Result = try + make_throw() + catch + Class:Reason -> + lager:pr_stacktrace(erlang:get_stacktrace(), {Class, Reason}) + end, +ExpectedPart = " + pr_stacktrace_test:pr_stacktrace_throw_test/0 line 18 + pr_stacktrace_test:make_throw/0 line 8 +throw:{test,exception}", + ?assertNotEqual(0, string:str(Result, ExpectedPart)). + + +pr_stacktrace_bad_arg_test() -> + Result = try + bad_arg() + catch + Class:Reason -> + lager:pr_stacktrace(erlang:get_stacktrace(), {Class, Reason}) + end, +ExpectedPart = " + pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 32 + pr_stacktrace_test:bad_arg/0 line 14 +error:badarg", + ?assertNotEqual(0, string:str(Result, ExpectedPart)). + + +pr_stacktrace_bad_arity_test() -> + Result = try + bad_arity() + catch + Class:Reason -> + lager:pr_stacktrace(erlang:get_stacktrace(), {Class, Reason}) + end, +ExpectedPart = " + pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46 + lists:concat([], []) +error:undef", + ?assertNotEqual(0, string:str(Result, ExpectedPart)). \ No newline at end of file diff -Nru erlang-lager-3.0.1/test/trunc_io_eqc.erl erlang-lager-3.1.0/test/trunc_io_eqc.erl --- erlang-lager-3.0.1/test/trunc_io_eqc.erl 2015-07-30 01:28:30.000000000 +0000 +++ erlang-lager-3.1.0/test/trunc_io_eqc.erl 2016-01-27 21:39:55.000000000 +0000 @@ -91,7 +91,7 @@ %% Generates a printable string gen_print_str() -> - ?LET(Xs, list(char()), [X || X <- Xs, io_lib:printable_list([X]), X /= $~, X < 255]). + ?LET(Xs, list(char()), [X || X <- Xs, io_lib:printable_list([X]), X /= $~, X < 256]). gen_print_bin() -> ?LET(Xs, gen_print_str(), list_to_binary(Xs)).