%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 2015-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. %% You may obtain a copy of the License at %% %% http://www.apache.org/licenses/LICENSE-2.0 %% %% Unless required by applicable law or agreed to in writing, software %% distributed under the License is distributed on an "AS IS" BASIS, %% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. %% See the License for the specific language governing permissions and %% limitations under the License. %% %% %CopyrightEnd% %% -module(error_logger_h_SUITE). -export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, init_per_group/2,end_per_group/2]). -export([logfile/1,logfile_truncated/1,tty/1,tty_truncated/1]). %% Event handler exports. -export([init/1,handle_event/2,terminate/2]). -include_lib("common_test/include/ct.hrl"). suite() -> [{ct_hooks,[ts_install_cth]}]. all() -> [logfile,logfile_truncated,tty,tty_truncated]. groups() -> []. init_per_suite(Config) -> Config. end_per_suite(_Config) -> ok. init_per_group(_GroupName, Config) -> Config. end_per_group(_GroupName, Config) -> Config. logfile(Config) -> PrivDir = proplists:get_value(priv_dir, Config), LogDir = filename:join(PrivDir, ?MODULE), Log = filename:join(LogDir, "logfile.log"), ok = filelib:ensure_dir(Log), Ev = event_templates(), do_one_logfile(Log, Ev, unlimited), Pa = "-pa " ++ filename:dirname(code:which(?MODULE)), {ok,Node} = start_node(logfile, Pa), error_logger:logfile({open,Log}), ok = rpc:call(Node, erlang, apply, [fun gen_events/1,[Ev]]), AtNode = iolist_to_binary(["** at node ",atom_to_list(Node)," **"]), timer:sleep(1000), % some time get all log events in the log error_logger:logfile(close), analyse_events(Log, Ev, [AtNode], unlimited), %% Make sure that the file_io_server process has been stopped [] = lists:filtermap( fun(X) -> case {process_info(X, [current_function]), file:pid2name(X)} of {[{current_function, {file_io_server, _, _}}], {ok,P2N = Log}} -> {true, {X, P2N}}; _ -> false end end, processes()), test_server:stop_node(Node), cleanup(Log), ok. logfile_truncated(Config) -> PrivDir = proplists:get_value(priv_dir, Config), LogDir = filename:join(PrivDir, ?MODULE), Log = filename:join(LogDir, "logfile_truncated.log"), ok = filelib:ensure_dir(Log), Ev = event_templates(), Depth = 20, application:set_env(kernel, error_logger_format_depth, Depth), try do_one_logfile(Log, Ev, Depth) after application:unset_env(kernel, error_logger_format_depth) end, cleanup(Log), ok. do_one_logfile(Log, Ev, Depth) -> error_logger:logfile({open,Log}), gen_events(Ev), error_logger:logfile(close), analyse_events(Log, Ev, [], Depth). tty(Config) -> PrivDir = proplists:get_value(priv_dir, Config), LogDir = filename:join(PrivDir, ?MODULE), Log = filename:join(LogDir, "tty.log"), ok = filelib:ensure_dir(Log), Ev = event_templates(), do_one_tty(Log, Ev, unlimited), Pa = "-pa " ++ filename:dirname(code:which(?MODULE)), {ok,Node} = start_node(tty, Pa), tty_log_open(Log), ok = rpc:call(Node, erlang, apply, [fun gen_events/1,[Ev]]), tty_log_close(), AtNode = iolist_to_binary(["** at node ",atom_to_list(Node)," **"]), timer:sleep(1000), % some time get all log events in the log analyse_events(Log, Ev, [AtNode], unlimited), test_server:stop_node(Node), cleanup(Log), ok. tty_truncated(Config) -> PrivDir = proplists:get_value(priv_dir, Config), LogDir = filename:join(PrivDir, ?MODULE), Log = filename:join(LogDir, "tty_truncated.log"), ok = filelib:ensure_dir(Log), Ev = event_templates(), Depth = 20, application:set_env(kernel, error_logger_format_depth, Depth), try do_one_tty(Log, Ev, Depth) after application:unset_env(kernel, error_logger_format_depth) end, cleanup(Log), ok. do_one_tty(Log, Ev, Depth) -> tty_log_open(Log), gen_events(Ev), tty_log_close(), analyse_events(Log, Ev, [], Depth). tty_log_open(Log) -> {ok,Fd} = file:open(Log, [write]), Depth = case application:get_env(kernel, error_logger_format_depth) of {ok,D} -> D; _ -> unlimited end, error_logger:add_report_handler(?MODULE, {Fd,Depth,latin1}), Fd. tty_log_close() -> error_logger:delete_report_handler(?MODULE), ok. event_templates() -> [{error_msg,["Pure error string\n",[]]}, {error_msg,["Pure error string with error ~p\n",[]]}, {error_msg,["Error string with ~p\n", [format]]}, {error_msg,["Error string with bad format ~p\n", []]}, {error_report,[error_atom]}, {error_report,["error string"]}, {error_report,[[{error_tag,value},error_value]]}, {info_msg,["Pure info string\n",[]]}, {info_msg,["Pure info string with error ~p\n",[]]}, {info_msg,["Pure string with ~p\n", [format]]}, {info_msg,["Pure string with bad format ~p\n", []]}, {info_report,[info_atom]}, {info_report,["info string"]}, {info_report,[[{info_tag,value},info_value]]}, {warning_msg,["Pure warning string\n",[]]}, {warning_msg,["Pure warning string with error ~p\n",[]]}, {warning_msg,["Warning string with ~p\n", [format]]}, {warning_msg,["Warning string with bad format ~p\n", []]}, {warning_report,[warning_atom]}, {warning_report,["warning string"]}, {warning_report,[[{warning_tag,value},warning_value]]}, %% Bigger terms. {error_msg,["fairly big: ~p\n",[lists:seq(1, 128)]]}, {error_report,[list_to_tuple(lists:seq(1, 100))]}, {error_report,[lists:seq(32, 126)]}, {error_report,[[{tag,lists:seq(1, 64)}]]} ]. gen_events(Ev) -> io:format("node = ~p\n", [node()]), io:format("group leader = ~p\n", [group_leader()]), io:format("~p\n", [error_logger:which_report_handlers()]), call_error_logger(Ev), {Pid,Ref} = spawn_monitor(fun() -> error(ouch) end), receive {'DOWN',Ref,process,Pid,_} -> ok end, %% The following calls with a custom type will be ignored. error_logger:error_report(ignored, value), error_logger:warning_report(ignored, value), error_logger:info_report(ignored, value), receive after 100 -> ok end, ok. analyse_events(Log, Ev, AtNode, Depth) -> {ok,Bin} = file:read_file(Log), io:format("*** Contents of log file ***\n\n~s\n", [Bin]), Lines = binary:split(Bin, <<"\n">>, [global,trim_all]), io:format("~p\n", [Lines]), Rest = match_output(Ev, Lines, AtNode, Depth), io:format("~p\n", [Rest]), [] = match_emulator_error(Rest), ok. call_error_logger([{F,Args}|T]) -> apply(error_logger, F, Args), timer:sleep(10), call_error_logger(T); call_error_logger([]) -> ok. match_emulator_error([Head,Second,Third,_|Lines]) -> match_head(<<"ERROR">>, Head), {match,[{0,_}]} = re:run(Second, "^Error in process <\\d+[.]\\d+[.]\\d+> on " "node [^ ]* with exit value:"), {match,[{0,_}]} = re:run(Third, "^[{]ouch,"), Lines. match_output([Item|T], Lines0, AtNode, Depth) -> try match_item(Item, Lines0, AtNode, Depth) of Lines -> match_output(T, Lines, AtNode, Depth) catch C:E:Stk -> io:format("ITEM: ~p", [Item]), io:format("LINES: ~p", [Lines0]), erlang:raise(C, E, Stk) end; match_output([], Lines, _, _) -> Lines. match_item(Item, Lines, AtNode, Depth) -> case item_type(Item) of {msg,Head,Args} -> match_format(Head, Args, Lines, AtNode, Depth); {report,Head,Args} -> match_term(Head, Args, Lines, AtNode, Depth) end. item_type({error_msg,Args}) -> {msg,<<"ERROR">>,Args}; item_type({info_msg,Args}) -> {msg,<<"INFO">>,Args}; item_type({warning_msg,Args}) -> {msg,<<"WARNING">>,Args}; item_type({error_report,Args}) -> {report,<<"ERROR">>,Args}; item_type({info_report,Args}) -> {report,<<"INFO">>,Args}; item_type({warning_report,Args}) -> {report,<<"WARNING">>,Args}. match_format(Tag, [Format,Args], [Head|Lines], AtNode, Depth) -> match_head(Tag, Head), Bin = try dl_format(Depth, Format, Args) of Str -> iolist_to_binary(Str) catch _:_ -> S = dl_format(Depth, "ERROR: ~p - ~p~n", [Format,Args]), iolist_to_binary(S) end, Expected0 = binary:split(Bin, <<"\n">>, [global,trim]), Expected = AtNode ++ Expected0, match_term_lines(Expected, Lines). match_term(Tag, [Arg], [Head|Lines], AtNode, Depth) -> match_head(Tag, Head), Expected0 = match_term_get_expected(Arg, Depth), Expected = AtNode ++ Expected0, match_term_lines(Expected, Lines). match_term_get_expected(List, Depth) when is_list(List) -> Bin = try iolist_to_binary(dl_format(Depth, "~s\n", [List])) of Bin0 -> Bin0 catch _:_ -> iolist_to_binary(format_rep(List, Depth)) end, binary:split(Bin, <<"\n">>, [global,trim]); match_term_get_expected(Term, Depth) -> S = dl_format(Depth, "~p\n", [Term]), Bin = iolist_to_binary(S), binary:split(Bin, <<"\n">>, [global,trim]). format_rep([{Tag,Data}|Rep], Depth) -> [dl_format(Depth, " ~p: ~p\n", [Tag,Data])| format_rep(Rep, Depth)]; format_rep([Other|Rep], Depth) -> [dl_format(Depth, " ~p\n", [Other])| format_rep(Rep, Depth)]; format_rep([], _Depth) -> []. match_term_lines([Line|T], [Line|Lines]) -> match_term_lines(T, Lines); match_term_lines([], Lines) -> Lines. match_head(Tag, Head) -> Re = <<"^=",Tag/binary, " REPORT==== \\d\\d?-[A-Z][a-z][a-z]-\\d{4}::" "\\d\\d:\\d\\d:\\d\\d ===$">>, {match,_} = re:run(Head, Re). start_node(Name, Args) -> case test_server:start_node(Name, slave, [{args,Args}]) of {ok,Node} -> {ok,Node}; Error -> ct:fail(Error) end. cleanup(File) -> %% The point of this test case is not to test file operations. %% Therefore ignore any failures. case file:delete(File) of ok -> ok; {error,Error1} -> io:format("file:delete(~s) failed with error ~p", [File,Error1]) end, Dir = filename:dirname(File), case file:del_dir(Dir) of ok -> ok; {error,Error2} -> io:format("file:del_dir(~s) failed with error ~p", [Dir,Error2]) end, ok. %% Depth-limited io_lib:format. Intentionally implemented here instead %% of using io_lib:scan_format/2 to avoid using the same implementation %% as in the error_logger handlers. dl_format(unlimited, Format, Args) -> io_lib:format(Format, Args); dl_format(Depth, Format0, Args0) -> {Format,Args} = dl_format_1(Format0, Args0, Depth, [], []), io_lib:format(Format, Args). dl_format_1("~p"++Fs, [A|As], Depth, Facc, Acc) -> dl_format_1(Fs, As, Depth, [$P,$~|Facc], [Depth,A|Acc]); dl_format_1("~w"++Fs, [A|As], Depth, Facc, Acc) -> dl_format_1(Fs, As, Depth, [$W,$~|Facc], [Depth,A|Acc]); dl_format_1("~s"++Fs, [A|As], Depth, Facc, Acc) -> dl_format_1(Fs, As, Depth, [$s,$~|Facc], [A|Acc]); dl_format_1([F|Fs], As, Depth, Facc, Aacc) -> dl_format_1(Fs, As, Depth, [F|Facc], Aacc); dl_format_1([], [], _, Facc, Aacc) -> {lists:reverse(Facc),lists:reverse(Aacc)}. %%% %%% Our own event handler. There is no way to intercept the output %%% from error_logger_tty_h, but we can use the same code by %%% calling error_logger_tty_h:write_event/2. %%% init({_,_,_}=St) -> {ok,St}. handle_event(Event, {Fd,Depth,Enc}=St) -> case error_logger_tty_h:write_event(tag_event(Event), io_lib, {Depth,Enc}) of ok -> ok; Str when is_list(Str) -> io:put_chars(Fd, Str) end, {ok,St}. terminate(_Reason, {Fd,_,_}) -> ok = file:close(Fd), []. tag_event(Event) -> {erlang:universaltime(),Event}.