Merge pull request #16 from basho/adt-simple_one_for_one-crash-report
Use mfargs instead of name attribute as the way to detect supervisor_bridge
diff --git a/README.org b/README.org
index f6bdfaf..de888a3 100644
--- a/README.org
+++ b/README.org
@@ -89,7 +89,7 @@
Or, for the backend with multiple handles (files, mainly):
#+BEGIN_EXAMPLE
- lager:set_loglevel(lager_file_backend, "console.log" debug).
+ lager:set_loglevel(lager_file_backend, "console.log", debug).
#+END_EXAMPLE
Lager keeps track of the minium log level being used by any backend and
diff --git a/rebar b/rebar
index f2bc4b8..8645775 100755
--- a/rebar
+++ b/rebar
Binary files differ
diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl
index 17d5a1b..7441c36 100644
--- a/src/error_logger_lager_h.erl
+++ b/src/error_logger_lager_h.erl
@@ -46,8 +46,14 @@
_ -> ok
end).
+-ifdef(TEST).
+%% Make CRASH synchronous when testing, to avoid timing headaches
+-define(CRASH_LOG(Event),
+ catch(gen_server:call(lager_crash_log, {log, Event}))).
+-else.
-define(CRASH_LOG(Event),
gen_server:cast(lager_crash_log, {log, Event})).
+-endif.
-spec init(any()) -> {ok, {}}.
init(_) ->
diff --git a/src/lager.app.src b/src/lager.app.src
index d1ad420..9ddb675 100644
--- a/src/lager.app.src
+++ b/src/lager.app.src
@@ -3,7 +3,7 @@
{application, lager,
[
{description, "Erlang logging framework"},
- {vsn, "0.9.0"},
+ {vsn, "0.9.2"},
{modules, []},
{applications, [
kernel,
diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl
index 430a046..75b2974 100644
--- a/src/lager_crash_log.erl
+++ b/src/lager_crash_log.erl
@@ -80,57 +80,16 @@
end.
%% @private
+handle_call({log, _} = Log, _From, State) ->
+ {Reply, NewState} = do_log(Log, State),
+ {reply, Reply, NewState};
handle_call(_Call, _From, State) ->
{reply, ok, State}.
%% @private
-handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap,
- fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count} = State) ->
- %% borrowed from riak_err
- {ReportStr, Pid, MsgStr, _ErrorP} = case Event of
- {error, _GL, {Pid1, Fmt, Args}} ->
- {"ERROR REPORT", Pid1, limited_fmt(Fmt, Args, FmtMaxBytes), true};
- {error_report, _GL, {Pid1, std_error, Rep}} ->
- {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes), true};
- {error_report, _GL, Other} ->
- perhaps_a_sasl_report(error_report, Other, FmtMaxBytes);
- _ ->
- {ignore, ignore, ignore, false}
- end,
- if ReportStr == ignore ->
- {noreply, State};
- true ->
- case lager_util:ensure_logfile(Name, FD, Inode, false) of
- {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize ->
- lager_util:rotate_logfile(Name, Count),
- handle_cast({log, Event}, State);
- {ok, {NewFD, NewInode, _Size}} ->
- {Date, TS} = lager_util:format_time(
- lager_stdlib:maybe_utc(erlang:localtime())),
- Time = [Date, " ", TS," =", ReportStr, "====\n"],
- NodeSuffix = other_node_suffix(Pid),
- Msg = io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix]),
- case file:write(NewFD, Msg) of
- {error, Reason} when Flap == false ->
- ?INT_LOG(error, "Failed to write log message to file ~s: ~s",
- [Name, file:format_error(Reason)]),
- {noreply, State#state{fd=NewFD, inode=NewInode, flap=true}};
- ok ->
- {noreply, State#state{fd=NewFD, inode=NewInode, flap=false}};
- _ ->
- {noreply, State#state{fd=NewFD, inode=NewInode}}
- end;
- {error, Reason} ->
- case Flap of
- true ->
- {noreply, State};
- _ ->
- ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s",
- [Name, file:format_error(Reason)]),
- {noreply, State#state{flap=true}}
- end
- end
- end;
+handle_cast({log, _} = Log, State) ->
+ {_, NewState} = do_log(Log, State),
+ {noreply, NewState};
handle_cast(_Request, State) ->
{noreply, State}.
@@ -221,6 +180,55 @@
sasl_limited_str(crash_report, Report, FmtMaxBytes) ->
lager_stdlib:proc_lib_format(Report, FmtMaxBytes).
+do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap,
+ fmtmaxbytes=FmtMaxBytes, size=RotSize, count=Count} = State) ->
+ %% borrowed from riak_err
+ {ReportStr, Pid, MsgStr, _ErrorP} = case Event of
+ {error, _GL, {Pid1, Fmt, Args}} ->
+ {"ERROR REPORT", Pid1, limited_fmt(Fmt, Args, FmtMaxBytes), true};
+ {error_report, _GL, {Pid1, std_error, Rep}} ->
+ {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes), true};
+ {error_report, _GL, Other} ->
+ perhaps_a_sasl_report(error_report, Other, FmtMaxBytes);
+ _ ->
+ {ignore, ignore, ignore, false}
+ end,
+ if ReportStr == ignore ->
+ {ok, State};
+ true ->
+ case lager_util:ensure_logfile(Name, FD, Inode, false) of
+ {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize ->
+ lager_util:rotate_logfile(Name, Count),
+ handle_cast({log, Event}, State);
+ {ok, {NewFD, NewInode, _Size}} ->
+ {Date, TS} = lager_util:format_time(
+ lager_stdlib:maybe_utc(erlang:localtime())),
+ Time = [Date, " ", TS," =", ReportStr, "====\n"],
+ NodeSuffix = other_node_suffix(Pid),
+ Msg = io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix]),
+ case file:write(NewFD, Msg) of
+ {error, Reason} when Flap == false ->
+ ?INT_LOG(error, "Failed to write log message to file ~s: ~s",
+ [Name, file:format_error(Reason)]),
+ {ok, State#state{fd=NewFD, inode=NewInode, flap=true}};
+ ok ->
+ {ok, State#state{fd=NewFD, inode=NewInode, flap=false}};
+ _ ->
+ {ok, State#state{fd=NewFD, inode=NewInode}}
+ end;
+ {error, Reason} ->
+ case Flap of
+ true ->
+ {ok, State};
+ _ ->
+ ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s",
+ [Name, file:format_error(Reason)]),
+ {ok, State#state{flap=true}}
+ end
+ end
+ end.
+
+
-ifdef(TEST).
filesystem_test_() ->
@@ -250,8 +258,8 @@
{"under normal circumstances, file should be opened",
fun() ->
{ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
- error_logger:error_msg("Test message\n"),
- timer:sleep(100),
+ _ = gen_event:which_handlers(error_logger),
+ sync_error_logger:error_msg("Test message\n"),
{ok, Bin} = file:read_file("crash_test.log"),
?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}]))
end
@@ -270,18 +278,17 @@
fun() ->
{ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
?assertEqual(0, lager_test_backend:count()),
- error_logger:error_msg("Test message\n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message\n"),
+ _ = gen_event:which_handlers(error_logger),
?assertEqual(1, lager_test_backend:count()),
file:delete("crash_test.log"),
file:write_file("crash_test.log", ""),
{ok, FInfo} = file:read_file_info("crash_test.log"),
file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}),
- error_logger:error_msg("Test message\n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message\n"),
+ _ = gen_event:which_handlers(error_logger),
?assertEqual(3, lager_test_backend:count()),
lager_test_backend:pop(),
- lager_test_backend:pop(),
{_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
?assertEqual("Failed to reopen crash log crash_test.log with error: permission denied", lists:flatten(Message))
end
@@ -296,8 +303,8 @@
{_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)),
file:write_file_info("crash_test.log", FInfo#file_info{mode = OldPerms}),
- error_logger:error_msg("Test message~n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message~n"),
+ _ = gen_event:which_handlers(error_logger),
{ok, Bin} = file:read_file("crash_test.log"),
?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}]))
end
@@ -306,19 +313,19 @@
fun() ->
{ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
?assertEqual(0, lager_test_backend:count()),
- error_logger:error_msg("Test message~n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message~n"),
+ _ = gen_event:which_handlers(error_logger),
{ok, Bin} = file:read_file("crash_test.log"),
?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])),
file:delete("crash_test.log"),
file:write_file("crash_test.log", ""),
- error_logger:error_msg("Test message1~n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message1~n"),
+ _ = gen_event:which_handlers(error_logger),
{ok, Bin1} = file:read_file("crash_test.log"),
?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])),
file:rename("crash_test.log", "crash_test.log.0"),
- error_logger:error_msg("Test message2~n"),
- timer:sleep(100),
+ sync_error_logger:error_msg("Test message2~n"),
+ _ = gen_event:which_handlers(error_logger),
{ok, Bin2} = file:read_file("crash_test.log"),
?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}]))
end
diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl
index 2562039..5debe3f 100644
--- a/src/lager_file_backend.erl
+++ b/src/lager_file_backend.erl
@@ -302,7 +302,6 @@
{ok, FInfo} = file:read_file_info("test.log"),
file:write_file_info("test.log", FInfo#file_info{mode = 0}),
lager:log(error, self(), "Test message"),
- timer:sleep(100),
?assertEqual(3, lager_test_backend:count()),
lager_test_backend:pop(),
lager_test_backend:pop(),
diff --git a/src/lager_trunc_io.erl b/src/lager_trunc_io.erl
index e0a6073..25841fe 100644
--- a/src/lager_trunc_io.erl
+++ b/src/lager_trunc_io.erl
@@ -102,12 +102,7 @@
{Value, RealLen} = case H of
"s" ->
% strip off the doublequotes, if applicable
- Trimmed = case {hd(String), lists:last(String)} == {$", $"} of
- true ->
- string:strip(String, both, $");
- _ ->
- String
- end,
+ Trimmed = unquote_string(lists:flatten(String)),
{Trimmed, length(Trimmed)};
_ ->
{String, Length}
@@ -136,8 +131,9 @@
{String, Length} ->
{Value, RealLen} = case C of
$s ->
- % strip off the doublequotes
- {string:substr(String, 2, length(String) -2), Length -2};
+ % strip off the doublequotes, if applicable
+ Trimmed = unquote_string(lists:flatten(String)),
+ {Trimmed, length(Trimmed)};
_ ->
{String, Length}
end,
@@ -235,7 +231,13 @@
print(Binary, Max) when is_binary(Binary) ->
B = binary_to_list(Binary, 1, lists:min([Max, size(Binary)])),
{L, Len} = alist_start(B, Max-4),
- {["<<", L, ">>"], Len+4};
+ {Res, Length} = case L of
+ [91, X, 93] ->
+ {X, Len - 2};
+ X ->
+ {X, Len}
+ end,
+ {["<<", Res, ">>"], Length+4};
print(Float, _Max) when is_float(Float) ->
%% use the same function io_lib:format uses to print floats
@@ -310,11 +312,23 @@
alist_start([], _) -> {"[]", 2};
alist_start(_, Max) when Max < 4 -> {"...", 3};
alist_start([H|T], Max) when is_integer(H), H >= 16#20, H =< 16#7e -> % definitely printable
- {L, Len} = alist([H|T], Max-1),
- {[$"|L], Len + 1};
-alist_start([H|T], Max) when H =:= 9; H =:= 10; H =:= 13 -> % show as space
- {L, Len} = alist(T, Max-1),
- {[$ |L], Len + 1};
+ try alist([H|T], Max -1) of
+ {L, Len} ->
+ {[$"|L], Len + 1}
+ catch
+ throw:unprintable ->
+ {R, Len} = list_body([H|T], Max-2),
+ {[$[, R, $]], Len + 2}
+ end;
+alist_start([H|T], Max) when H =:= 9; H =:= 10; H =:= 13 ->
+ try alist([H|T], Max -1) of
+ {L, Len} ->
+ {[$"|L], Len + 1}
+ catch
+ throw:unprintable ->
+ {R, Len} = list_body([H|T], Max-2),
+ {[$[, R, $]], Len + 2}
+ end;
alist_start(L, Max) ->
{R, Len} = list_body(L, Max-2),
{[$[, R, $]], Len + 2}.
@@ -324,12 +338,11 @@
alist([H|T], Max) when is_integer(H), H >= 16#20, H =< 16#7e -> % definitely printable
{L, Len} = alist(T, Max-1),
{[H|L], Len + 1};
-alist([H|T], Max) when H =:= 9; H =:= 10; H =:= 13 -> % show as space
+alist([H|T], Max) when H =:= 9; H =:= 10; H =:= 13 ->
{L, Len} = alist(T, Max-1),
- {[$ |L], Len + 1};
-alist(L, Max) ->
- {R, Len} = list_body(L, Max-3),
- {[$", $[, R, $]], Len + 3}.
+ {[H|L], Len + 1};
+alist(_L, _Max) ->
+ throw(unprintable).
%% is the first character in the atom alphabetic & lowercase?
atom_needs_quoting_start([H|T]) when H >= $a, H =< $z ->
@@ -346,6 +359,30 @@
atom_needs_quoting(_) ->
true.
+unquote_string([$<, $<, $"|T] = Str) ->
+ case string:substr(T, length(T) - 2) of
+ "\">>" ->
+ string:substr(T, 1, length(T) - 3);
+ _ ->
+ Str
+ end;
+unquote_string([$"|_] = Str) ->
+ case lists:last(Str) == $" of
+ true ->
+ string:strip(Str, both, $");
+ _ ->
+ Str
+ end;
+unquote_string([$'|_] = Str) ->
+ case lists:last(Str) == $' of
+ true ->
+ string:strip(Str, both, $');
+ _ ->
+ Str
+ end;
+unquote_string(S) ->
+ S.
+
-ifdef(TEST).
%%--------------------
%% The start of a test suite. So far, it only checks for not crashing.
@@ -435,8 +472,8 @@
ok.
float_inside_list_test() ->
- ?assertEqual("\"a\"[38.233913133184835,99]", lists:flatten(format("~p", [[$a, 38.233913133184835, $c]], 50))),
- ?assertEqual("\"a\"[38.233913133184835,99]", lists:flatten(format("~s", [[$a, 38.233913133184835, $c]], 50))),
+ ?assertEqual("[97,38.233913133184835,99]", lists:flatten(format("~p", [[$a, 38.233913133184835, $c]], 50))),
+ ?assertEqual("[97,38.233913133184835,99]", lists:flatten(format("~s", [[$a, 38.233913133184835, $c]], 50))),
ok.
quote_strip_test() ->
@@ -444,5 +481,28 @@
?assertEqual("hello", lists:flatten(format("~s", ["hello"], 50))),
?assertEqual("hello", lists:flatten(format("~s", [hello], 50))),
?assertEqual("hello", lists:flatten(format("~p", [hello], 50))),
+ ?assertEqual("'hello world'", lists:flatten(format("~p", ['hello world'], 50))),
+ ?assertEqual("hello world", lists:flatten(format("~s", ['hello world'], 50))),
+ ok.
+
+binary_printing_test() ->
+ ?assertEqual("<<\"hello\">>", lists:flatten(format("~p", [<<$h, $e, $l, $l, $o>>], 50))),
+ ?assertEqual("<<\"hello\">>", lists:flatten(format("~p", [<<"hello">>], 50))),
+ ?assertEqual("<<1,2,3,4>>", lists:flatten(format("~p", [<<1, 2, 3, 4>>], 50))),
+ ?assertEqual("<<1,2,3,4>>", lists:flatten(format("~s", [<<1, 2, 3, 4>>], 50))),
+ ?assertEqual("hello", lists:flatten(format("~s", [<<"hello">>], 50))),
+ ?assertEqual("hello", lists:flatten(format("~10s", [<<"hello">>], 50))),
+ ok.
+
+list_printing_test() ->
+ ?assertEqual("[13,11,10,8,5,4]", lists:flatten(format("~p", [[13,11,10,8,5,4]], 50))),
+ ?assertEqual("[1,2,3|4]", lists:flatten(format("~p", [[1, 2, 3|4]], 50))),
+ ?assertEqual("[1|4]", lists:flatten(format("~p", [[1|4]], 50))),
+ ?assertEqual("\"hello...\"", lists:flatten(format("~p", ["hello world"], 10))),
+ ?assertEqual("hello...", lists:flatten(format("~s", ["hello world"], 10))),
+ ?assertEqual("hello world\r\n", lists:flatten(format("~s", ["hello world\r\n"], 50))),
+ ?assertEqual("\rhello world\r\n", lists:flatten(format("~s", ["\rhello world\r\n"], 50))),
+ ?assertEqual("...", lists:flatten(format("~s", ["\rhello world\r\n"], 3))),
+ ?assertEqual("[]", lists:flatten(format("~s", [[]], 50))),
ok.
-endif.
diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl
index c216d44..445f5ce 100644
--- a/test/lager_test_backend.erl
+++ b/test/lager_test_backend.erl
@@ -194,12 +194,8 @@
crash(Type) ->
spawn(fun() -> gen_server:call(crash, Type) end),
- timer:sleep(100).
-
-custom_sleep(MSec) ->
- timer:sleep(MSec),
- [_|_] = gen_event:which_handlers(error_logger),
- [_|_] = gen_event:which_handlers(lager_event),
+ timer:sleep(100),
+ _ = gen_event:which_handlers(error_logger),
ok.
error_logger_redirect_crash_test_() ->
@@ -375,6 +371,7 @@
application:set_env(lager, error_logger_redirect, true),
application:set_env(lager, handlers, [{?MODULE, info}]),
application:start(lager),
+ lager:log(error, self(), "flush flush"),
timer:sleep(100),
gen_event:call(lager_event, ?MODULE, flush)
end,
@@ -386,8 +383,8 @@
[
{"error reports are printed",
fun() ->
- error_logger:error_report([{this, is}, a, {silly, format}]),
- custom_sleep(100),
+ sync_error_logger:error_report([{this, is}, a, {silly, format}]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w this: is, a, silly: format", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -395,8 +392,8 @@
},
{"string error reports are printed",
fun() ->
- error_logger:error_report("this is less silly"),
- custom_sleep(100),
+ sync_error_logger:error_report("this is less silly"),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w this is less silly", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -404,8 +401,8 @@
},
{"error messages are printed",
fun() ->
- error_logger:error_msg("doom, doom has come upon you all"),
- custom_sleep(100),
+ sync_error_logger:error_msg("doom, doom has come upon you all"),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w doom, doom has come upon you all", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -413,16 +410,16 @@
},
{"error messages are truncated at 4096 characters",
fun() ->
- error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
- custom_sleep(1000),
+ sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
?assert(length(lists:flatten(Msg)) < 5100)
end
},
{"info reports are printed",
fun() ->
- error_logger:info_report([{this, is}, a, {silly, format}]),
- custom_sleep(100),
+ sync_error_logger:info_report([{this, is}, a, {silly, format}]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w this: is, a, silly: format", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -430,16 +427,16 @@
},
{"info reports are truncated at 4096 characters",
fun() ->
- error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]),
- custom_sleep(1000),
+ sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
?assert(length(lists:flatten(Msg)) < 5000)
end
},
{"single term info reports are printed",
fun() ->
- error_logger:info_report({foolish, bees}),
- custom_sleep(100),
+ sync_error_logger:info_report({foolish, bees}),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w {foolish,bees}", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -447,8 +444,8 @@
},
{"single term error reports are printed",
fun() ->
- error_logger:error_report({foolish, bees}),
- custom_sleep(100),
+ sync_error_logger:error_report({foolish, bees}),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w {foolish,bees}", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -456,8 +453,8 @@
},
{"string info reports are printed",
fun() ->
- error_logger:info_report("this is less silly"),
- custom_sleep(100),
+ sync_error_logger:info_report("this is less silly"),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w this is less silly", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -465,8 +462,8 @@
},
{"string info reports are truncated at 4096 characters",
fun() ->
- error_logger:info_report(string:copies("this is less silly", 1000)),
- custom_sleep(1000),
+ sync_error_logger:info_report(string:copies("this is less silly", 1000)),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
?assert(length(lists:flatten(Msg)) < 5100)
end
@@ -474,8 +471,8 @@
{"info messages are printed",
fun() ->
- error_logger:info_msg("doom, doom has come upon you all"),
- custom_sleep(100),
+ sync_error_logger:info_msg("doom, doom has come upon you all"),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w doom, doom has come upon you all", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -483,8 +480,8 @@
},
{"info messages are truncated at 4096 characters",
fun() ->
- error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
- custom_sleep(1000),
+ sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
?assert(length(lists:flatten(Msg)) < 5100)
end
@@ -492,9 +489,9 @@
{"warning messages are printed at the correct level",
fun() ->
- error_logger:warning_msg("doom, doom has come upon you all"),
+ sync_error_logger:warning_msg("doom, doom has come upon you all"),
Map = error_logger:warning_map(),
- custom_sleep(100),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[~w] ~w doom, doom has come upon you all", [Map, self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -502,9 +499,9 @@
},
{"warning reports are printed at the correct level",
fun() ->
- error_logger:warning_report([{i, like}, pie]),
+ sync_error_logger:warning_report([{i, like}, pie]),
Map = error_logger:warning_map(),
- custom_sleep(100),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[~w] ~w i: like, pie", [Map, self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -512,9 +509,9 @@
},
{"single term warning reports are printed at the correct level",
fun() ->
- error_logger:warning_report({foolish, bees}),
+ sync_error_logger:warning_report({foolish, bees}),
Map = error_logger:warning_map(),
- custom_sleep(100),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[~w] ~w {foolish,bees}", [Map, self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -522,8 +519,8 @@
},
{"application stop reports",
fun() ->
- error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]),
- custom_sleep(100),
+ sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w Application foo exited with reason: quittin_time", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -531,8 +528,8 @@
},
{"supervisor reports",
fun() ->
- error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
- custom_sleep(100),
+ 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),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -540,8 +537,8 @@
},
{"supervisor reports with real error",
fun() ->
- 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}}]),
- custom_sleep(100),
+ 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),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w 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", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -550,8 +547,8 @@
{"supervisor_bridge reports",
fun() ->
- error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
- custom_sleep(100),
+ 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),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -559,8 +556,8 @@
},
{"application progress report",
fun() ->
- error_logger:info_report(progress, [{application, foo}, {started_at, node()}]),
- custom_sleep(100),
+ sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[info] ~w Application foo started on node ~w", [self(), node()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -569,8 +566,8 @@
{"supervisor progress report",
fun() ->
lager:set_loglevel(?MODULE, debug),
- error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]),
- custom_sleep(100),
+ sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[debug] ~w Supervisor foo started foo:bar/1 at pid baz", [self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -578,8 +575,8 @@
},
{"crash report for emfile",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {emfile, [{stack, trace, 1}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {emfile, [{stack, trace, 1}]}, []}}], []]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -587,8 +584,8 @@
},
{"crash report for system process limit",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn, 1}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn, 1}]}, []}}], []]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -596,8 +593,8 @@
},
{"crash report for system process limit2",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn_opt, 1}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, spawn_opt, 1}]}, []}}], []]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -605,8 +602,8 @@
},
{"crash report for system port limit",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, open_port, 1}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, open_port, 1}]}, []}}], []]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -614,8 +611,8 @@
},
{"crash report for system port limit",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, list_to_atom, 1}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit, [{erlang, list_to_atom, 1}]}, []}}], []]),
+ _ = gen_event:which_handlers(error_logger),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w 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(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -623,8 +620,8 @@
},
{"crash report for system ets table limit",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {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}]}, []}}], []]),
- custom_sleep(100),
+ sync_error_logger:error_report(crash_report, [[{pid, self()}, {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),
{_, _, Msg} = pop(),
Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [self(), self()])),
?assertEqual(Expected, lists:flatten(Msg))
@@ -632,8 +629,8 @@
},
{"crash report for unknown system limit should be truncated at 500 characters",
fun() ->
- error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, {system_limit,[{wtf,boom,[string:copies("aaaa", 4096)]}]}, []}}], []]),
- custom_sleep(1000),
+ 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} = pop(),
?assert(length(lists:flatten(Msg)) > 500),
?assert(length(lists:flatten(Msg)) < 700)
@@ -642,19 +639,19 @@
{"messages should not be generated if they don't satisfy the threshold",
fun() ->
lager:set_loglevel(?MODULE, error),
- error_logger:info_report([hello, world]),
- custom_sleep(100),
+ 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),
- error_logger:info_report([hello, world]),
- custom_sleep(100),
+ 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),
lager_mochiglobal:put(loglevel, ?DEBUG),
- error_logger:info_report([hello, world]),
- custom_sleep(100),
+ sync_error_logger:info_report([hello, world]),
+ _ = gen_event:which_handlers(error_logger),
?assertEqual(1, count()),
?assertEqual(1, count_ignored())
end
diff --git a/test/sync_error_logger.erl b/test/sync_error_logger.erl
new file mode 100644
index 0000000..078000f
--- /dev/null
+++ b/test/sync_error_logger.erl
@@ -0,0 +1,89 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 1996-2009. All Rights Reserved.
+%%
+%% The contents of this file are subject to the Erlang Public License,
+%% Version 1.1, (the "License"); you may not use this file except in
+%% compliance with the License. You should have received a copy of the
+%% Erlang Public License along with this software. If not, it can be
+%% retrieved online at http://www.erlang.org/.
+%%
+%% Software distributed under the License is distributed on an "AS IS"
+%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
+%% the License for the specific language governing rights and limitations
+%% under the License.
+%%
+%% %CopyrightEnd%
+%%
+-module(sync_error_logger).
+
+%% The error_logger API, but synchronous!
+%% This is helpful for tests, otherwise you need lots of nasty timer:sleep.
+%% Additionally, the warning map can be set on a per-process level, for
+%% convienience, via the process dictionary value `warning_map'.
+
+-export([
+ info_msg/1, info_msg/2,
+ warning_msg/1, warning_msg/2,
+ error_msg/1,error_msg/2
+ ]).
+
+-export([
+ info_report/1, info_report/2,
+ warning_report/1, warning_report/2,
+ error_report/1, error_report/2
+ ]).
+
+info_msg(Format) ->
+ info_msg(Format, []).
+
+info_msg(Format, Args) ->
+ gen_event:sync_notify(error_logger, {info_msg, group_leader(), {self(), Format, Args}}).
+
+warning_msg(Format) ->
+ warning_msg(Format, []).
+
+warning_msg(Format, Args) ->
+ gen_event:sync_notify(error_logger, {warning_msg_tag(), group_leader(), {self(), Format, Args}}).
+
+error_msg(Format) ->
+ error_msg(Format, []).
+
+error_msg(Format, Args) ->
+ gen_event:sync_notify(error_logger, {error, group_leader(), {self(), Format, Args}}).
+
+info_report(Report) ->
+ info_report(std_info, Report).
+
+info_report(Type, Report) ->
+ gen_event:sync_notify(error_logger, {info_report, group_leader(), {self(), Type, Report}}).
+
+warning_report(Report) ->
+ warning_report(std_warning, Report).
+
+warning_report(Type, Report) ->
+ {Tag, NType} = warning_report_tag(Type),
+ gen_event:sync_notify(error_logger, {Tag, group_leader(), {self(), NType, Report}}).
+
+error_report(Report) ->
+ error_report(std_error, Report).
+
+error_report(Type, Report) ->
+ gen_event:sync_notify(error_logger, {error_report, group_leader(), {self(), Type, Report}}).
+
+warning_msg_tag() ->
+ case get(warning_map) of
+ warning -> warning_msg;
+ info -> info_msg;
+ _ -> error
+ end.
+
+warning_report_tag(Type) ->
+ case {get(warning_map), Type == std_warning} of
+ {warning, _} -> {warning_report, Type};
+ {info, true} -> {info_report, std_info};
+ {info, false} -> {info_report, Type};
+ {_, true} -> {error_report, std_error};
+ {_, false} -> {error_report, Type}
+ end.
