Merge branch 'siri/logger-fix'

* siri/logger-fix:
  Change logger callback removing_handler/1 to removing_handler/2
  Don't crash logger_server due to unexpected message
  Add logger:update_process_metadata/1
  Improve documentation of logger:set_*_config functions
  Change return type from logger_formatter:format/2
  Improve test of logger_disk_log_h and logger_std_h
  Update logger documentation
  Set single_line=true by default in logger_formatter

4 files changed, 164 insertions, 105 deletions

diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl
index 0edce3e34c..f311a9c7ed 100644
--- a/lib/kernel/test/logger_SUITE.erl
+++ b/lib/kernel/test/logger_SUITE.erl
@@ -666,6 +666,9 @@ process_metadata(_Config) ->
     check_logged(info,S3,#{time=>Time,line=>0,custom=>func}),
 
     ProcMeta = logger:get_process_metadata(),
+    ok = logger:update_process_metadata(#{custom=>changed,custom2=>added}),
+    Expected = ProcMeta#{custom:=changed,custom2=>added},
+    Expected = logger:get_process_metadata(),
     ok = logger:unset_process_metadata(),
     undefined = logger:get_process_metadata(),
 
@@ -720,7 +723,7 @@ check_maps(Expected,Got,What) ->
 adding_handler(_Id,Config) ->
     maybe_send(add),
     {ok,Config}.
-removing_handler(_Id) ->
+removing_handler(_Id,_Config) ->
     maybe_send(remove),
     ok.
 changing_config(_Id,_Old,#{call:=Fun}) ->
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index c7c6137380..63e5b56021 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -497,24 +497,19 @@ disk_log_sync(Config) ->
                               filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
                               formatter=>{?MODULE,nl}}),
 
-    start_tracer([{?MODULE,format,2},
-                  {disk_log,blog,2},
+    start_tracer([{disk_log,blog,2},
                   {disk_log,sync,1}],
-                 [{formatter,"first"},
-                  {disk_log,blog},
+                 [{disk_log,blog,<<"first\n">>},
                   {disk_log,sync}]),
 
     logger:info("first", ?domain),
     %% wait for automatic disk_log_sync
     check_tracer(?FILESYNC_REPEAT_INTERVAL*2),
     
-    start_tracer([{?MODULE,format,2},
-                  {disk_log,blog,2},
+    start_tracer([{disk_log,blog,2},
                   {disk_log,sync,1}],
-                 [{formatter,"second"},
-                  {formatter,"third"},
-                  {disk_log,blog},
-                  {disk_log,blog},
+                 [{disk_log,blog,<<"second\n">>},
+                  {disk_log,blog,<<"third\n">>},
                   {disk_log,sync}]),
     %% two log requests in fast succession will make the handler skip
     %% an automatic disk log sync
@@ -531,13 +526,10 @@ disk_log_sync(Config) ->
     no_repeat = maps:get(filesync_repeat_interval,
                          logger_disk_log_h:info(?MODULE)),
 
-    start_tracer([{?MODULE,format,2},
-                  {disk_log,blog,2},
+    start_tracer([{disk_log,blog,2},
                   {disk_log,sync,1}],
-                 [{formatter,"fourth"},
-                  {disk_log,blog},
-                  {formatter,"fifth"},
-                  {disk_log,blog},
+                 [{disk_log,blog,<<"fourth\n">>},
+                  {disk_log,blog,<<"fifth\n">>},
                   {disk_log,sync}]),
 
     logger:info("fourth", ?domain),
@@ -566,6 +558,7 @@ disk_log_sync(Config) ->
     check_tracer(100),
     ok.
 disk_log_sync(cleanup,_Config) ->
+    dbg:stop_clear(),
     logger:remove_handler(?MODULE).
 
 disk_log_wrap(Config) ->
@@ -623,6 +616,7 @@ disk_log_wrap(Config) ->
     ok.
 
 disk_log_wrap(cleanup,_Config) ->
+    dbg:stop_clear(),
     logger:remove_handler(?MODULE).
 
 disk_log_full(Config) ->
@@ -668,6 +662,7 @@ disk_log_full(Config) ->
      {trace,{error_status,{error,{full,_}}}}] = Received,
     ok.
 disk_log_full(cleanup, _Config) ->
+    dbg:stop_clear(),
     logger:remove_handler(?MODULE).    
 
 disk_log_events(Config) ->
@@ -713,6 +708,7 @@ disk_log_events(Config) ->
                   end, Received),
     ok.
 disk_log_events(cleanup, _Config) ->
+    dbg:stop_clear(),
     logger:remove_handler(?MODULE).    
 
 write_failure(Config) ->
@@ -763,7 +759,7 @@ sync_failure(Config) ->
     Dir = ?config(priv_dir, Config),
     FileName = lists:concat([?MODULE,"_",?FUNCTION_NAME]),
     File = filename:join(Dir, FileName),
-    Log = lists:concat([File,".1"]),
+
 
     Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File),
     false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])),
@@ -832,10 +828,10 @@ log_on_remote_node(Node,Msg) ->
     ok.
 
 %% functions for test hook macros to be called by rpc
-set_internal_log(Mod, Func) ->
-    ?set_internal_log({Mod,Func}).
-set_result(Op, Result) ->
-    ?set_result(Op, Result).
+set_internal_log(_Mod, _Func) ->
+    ?set_internal_log({_Mod,_Func}).
+set_result(_Op, _Result) ->
+    ?set_result(_Op, _Result).
 set_defaults() ->
     ?set_defaults().
 
@@ -885,7 +881,7 @@ op_switch_to_drop(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 op_switch_to_flush() ->
-    [{timetrap,{seconds,60}}].
+    [{timetrap,{minutes,3}}].
 op_switch_to_flush(Config) ->
     {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     
@@ -988,7 +984,7 @@ kill_disabled(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 qlen_kill_new(Config) ->
-    {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+    {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     Pid0 = whereis(?MODULE),
     {_,Mem0} = process_info(Pid0, memory),
     RestartAfter = 2000,
@@ -1025,7 +1021,7 @@ qlen_kill_new(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 mem_kill_new(Config) ->
-    {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+    {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     Pid0 = whereis(?MODULE),
     {_,Mem0} = process_info(Pid0, memory),
     RestartAfter = 2000,
@@ -1111,7 +1107,7 @@ restart_after(cleanup, _Config) ->
 %% during high load to verify that sync, dropping and flushing is
 %% handled correctly.
 handler_requests_under_load() ->
-    [{timetrap,{seconds,60}}].
+    [{timetrap,{minutes,3}}].
 handler_requests_under_load(Config) ->
     {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     NewHConfig =
@@ -1140,7 +1136,7 @@ handler_requests_under_load(Config) ->
     NoOfReqs = lists:foldl(fun({_,Res}, N) -> N + length(Res) end, 0, ReqResult),
     ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]),
     ok = file:delete(Log).
-handler_requests_under_load(cleanup, Config) ->
+handler_requests_under_load(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) ->
@@ -1369,7 +1365,6 @@ start_tracer(Trace,Expected) ->
     Pid = self(),
     dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
     dbg:p(whereis(?MODULE),[c]),
-    dbg:p(Pid,[c]),
     tpl(Trace),
     ok.
 
@@ -1387,13 +1382,14 @@ tpl([{M,F,A}|Trace]) ->
 tpl([]) ->
     ok.
 
-tracer({trace,_,call,{?MODULE,format,[#{msg:={string,Msg}}|_]}}, {Pid,[{formatter,Msg}|Expected]}) ->
-    maybe_tracer_done(Pid,Expected,{formatter,Msg});
 tracer({trace,_,call,{logger_disk_log_h,handle_cast,[{Op,_}|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) ->
     maybe_tracer_done(Pid,Expected,{Mod,Func,Op});
+tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]}}, {Pid,[{Mod,Func,Data}|Expected]}) ->
+    maybe_tracer_done(Pid,Expected,{Mod,Func,Data});
 tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) ->
     maybe_tracer_done(Pid,Expected,{Mod,Func});
 tracer({trace,_,call,Call}, {Pid,Expected}) ->
+    ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]),
     Pid ! {tracer_got_unexpected,Call,Expected},
     {Pid,Expected}.
 
@@ -1413,5 +1409,6 @@ check_tracer(T) ->
             dbg:stop_clear(),
             ct:fail({tracer_got_unexpected,Got,Expected})
     after T ->
+            dbg:stop_clear(),
             ct:fail({timeout,tracer})
     end.
diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl
index ac1abba629..7d1f33746d 100644
--- a/lib/kernel/test/logger_formatter_SUITE.erl
+++ b/lib/kernel/test/logger_formatter_SUITE.erl
@@ -73,18 +73,19 @@ all() ->
 default(_Config) ->
     String1 = format(info,{"~p",[term]},#{},#{}),
     ct:log(String1),
-    [_Date,_Time,"info:\nterm\n"] = string:lexemes(String1," "),
+    [_Date,_Time,"info:","term\n"] = string:lexemes(String1," "),
 
     Time = timestamp(),
     ExpectedTimestamp = default_time_format(Time),
     String2 = format(info,{"~p",[term]},#{time=>Time},#{}),
     ct:log(String2),
-    " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), 
+    " info: term\n" = string:prefix(String2,ExpectedTimestamp),
     ok.
 
 legacy_header(_Config) ->
     Time = timestamp(),
-    String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true}),
+    String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true,
+                                                        single_line=>false}),
     ct:log(String1),
     "=INFO REPORT==== "++Rest = String1,
     [Timestamp,"\nterm\n"] = string:lexemes(Rest," ="),
@@ -98,12 +99,14 @@ legacy_header(_Config) ->
     true = lists:member(M,["Jan","Feb","Mar","Apr","May","Jun",
                            "Jul","Aug","Sep","Oct","Nov","Dec"]),
 
-    String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false}),
+    String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false,
+                                                        single_line=>false}),
     ct:log(String2),
     ExpectedTimestamp = default_time_format(Time),
     " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), 
     
-    String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad}),
+    String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad,
+                                                        single_line=>false}),
     ct:log(String3),
     String3 = String2,
 
@@ -114,7 +117,8 @@ legacy_header(_Config) ->
     String4 = String1,
 
     String5 = format(info,{"~p",[term]},#{}, % <--- no time
-                     #{legacy_header=>true}),
+                     #{legacy_header=>true,
+                       single_line=>false}),
     ct:log(String5),
     "=INFO REPORT==== "++_ = String5,
     ok.
@@ -289,38 +293,36 @@ report_cb(_Config) ->
     ok.
 
 max_size(_Config) ->
-    Template = [msg],
+    Cfg = #{template=>[msg],
+            single_line=>false},
     "12345678901234567890" =
-        format(info,{"12345678901234567890",[]},#{},#{template=>Template}),
+        format(info,{"12345678901234567890",[]},#{},Cfg),
     application:set_env(kernel,logger_max_size,11),
     "12345678901234567890" = % min value is 50, so this is not limited
-        format(info,{"12345678901234567890",[]},#{},#{template=>Template}),
+        format(info,{"12345678901234567890",[]},#{},Cfg),
     "12345678901234567890123456789012345678901234567..." = % 50
         format(info,
                {"123456789012345678901234567890123456789012345678901234567890",
                 []},
                #{},
-               #{template=>Template}),
+               Cfg),
     application:set_env(kernel,logger_max_size,53),
     "12345678901234567890123456789012345678901234567890..." = %53
         format(info,
                {"123456789012345678901234567890123456789012345678901234567890",
                 []},
                #{},
-               #{template=>Template}),
+               Cfg),
     "123456789012..." =
-        format(info,{"12345678901234567890",[]},#{},#{template=>Template,
-                                                      max_size=>15}),
+        format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}),
     "12345678901234567890" =
-        format(info,{"12345678901234567890",[]},#{},#{template=>Template,
-                                                      max_size=>unlimited}),
+        format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>unlimited}),
     %% Check that one newline at the end of the line is kept (if it exists)
     "12345678901...\n" =
-        format(info,{"12345678901234567890\n",[]},#{},#{template=>Template,
-                                                        max_size=>15}),
+        format(info,{"12345678901234567890\n",[]},#{},Cfg#{max_size=>15}),
     "12345678901...\n" =
-        format(info,{"12345678901234567890",[]},#{},#{template=>[msg,"\n"],
-                                                      max_size=>15}),
+        format(info,{"12345678901234567890",[]},#{},Cfg#{template=>[msg,"\n"],
+                                                         max_size=>15}),
     ok.
 max_size(cleanup,_Config) ->
     application:unset_env(kernel,logger_max_size),
@@ -441,20 +443,20 @@ format_time(_Config) ->
     ExpectedTimestamp1 = default_time_format(Time1),
     String1 = format(info,{"~p",[term]},#{time=>Time1},#{}),
     ct:log(String1),
-    " info:\nterm\n" = string:prefix(String1,ExpectedTimestamp1),
+    " info: term\n" = string:prefix(String1,ExpectedTimestamp1),
 
     Time2 = timestamp(),
     ExpectedTimestamp2 = default_time_format(Time2,true),
     String2 = format(info,{"~p",[term]},#{time=>Time2},#{utc=>true}),
     ct:log(String2),
-    " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp2),
+    " info: term\n" = string:prefix(String2,ExpectedTimestamp2),
 
     application:set_env(kernel,logger_utc,true),
     Time3 = timestamp(),
     ExpectedTimestamp3 = default_time_format(Time3,true),
     String3 = format(info,{"~p",[term]},#{time=>Time3},#{}),
     ct:log(String3),
-    " info:\nterm\n" = string:prefix(String3,ExpectedTimestamp3),
+    " info: term\n" = string:prefix(String3,ExpectedTimestamp3),
 
     ok.
 
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index e940e0a026..7c8d63cbbd 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -499,86 +499,79 @@ filesync(Config) ->
                             #{logger_std_h => #{type => Type},
                               filter_default=>log,
                               filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
-                              formatter=>{?MODULE,self()}}),
-    Tester = self(),
-    TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) ->
-                       Pid ! {trace,Mod,Func,Details},
-                       Pid;
-                  ({trace,TPid,'receive',Received}, Pid) ->
-                       Pid ! {trace,TPid,Received},
-                       Pid
-               end,
-    {ok,_} = dbg:tracer(process, {TraceFun, Tester}),
-    FileCtrlPid = maps:get(file_ctrl_pid , logger_std_h:info(?MODULE)),
-    {ok,_} = dbg:p(FileCtrlPid, [c]),
-    {ok,_} = dbg:tpl(logger_std_h, write_to_dev, 5, []),
-    {ok,_} = dbg:tpl(logger_std_h, sync_dev, 4, []),
-    {ok,_} = dbg:tp(file, datasync, 1, []),
+                              formatter=>{?MODULE,nl}}),
+
+    %% check repeated filesync happens
+    start_tracer([{logger_std_h, write_to_dev, 5},
+                  {logger_std_h, sync_dev, 4},
+                  {file, datasync, 1}],
+                 [{logger_std_h, write_to_dev, <<"first\n">>},
+                  {logger_std_h, sync_dev},
+                  {file,datasync}]),
 
     logger:info("first", ?domain),
     %% wait for automatic filesync
-    timer:sleep(?FILESYNC_REP_INT),
-    Expected1 = [{log,"first"}, {trace,logger_std_h,write_to_dev},
-                 {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
-    
+    check_tracer(?FILESYNC_REP_INT*2),
+
+    %% check that explicit filesync is only done once
+    start_tracer([{logger_std_h, write_to_dev, 5},
+                  {logger_std_h, sync_dev, 4},
+                  {file, datasync, 1}],
+                 [{logger_std_h, write_to_dev, <<"second\n">>},
+                  {logger_std_h, sync_dev},
+                  {file,datasync},
+                  {no_more,500}
+                 ]),
     logger:info("second", ?domain),
     %% do explicit filesync
     logger_std_h:filesync(?MODULE),
     %% a second filesync should be ignored
     logger_std_h:filesync(?MODULE),
-    Expected2 =  [{log,"second"}, {trace,logger_std_h,write_to_dev},
-                  {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
+    check_tracer(100),
 
     %% check that if there's no repeated filesync active,
     %% a filesync is still performed when handler goes idle
     logger:set_handler_config(?MODULE, logger_std_h,
                               #{filesync_repeat_interval => no_repeat}),
     no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)),
+    %% The following timer is to make sure the time from last log
+    %% ("second") to next ("third") is long enough, so the a flush is
+    %% triggered by the idle timeout between "thrid" and "fourth".
+    timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
+    start_tracer([{logger_std_h, write_to_dev, 5},
+                  {logger_std_h, sync_dev, 4},
+                  {file, datasync, 1}],
+                 [{logger_std_h, write_to_dev, <<"third\n">>},
+                  {logger_std_h, sync_dev},
+                  {file,datasync},
+                  {logger_std_h, write_to_dev, <<"fourth\n">>},
+                  {logger_std_h, sync_dev},
+                  {file,datasync}]),
     logger:info("third", ?domain),
+    %% wait for automatic filesync
     timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
     logger:info("fourth", ?domain),
     %% wait for automatic filesync
-    timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
-    Expected3 = [{log,"third"}, {trace,logger_std_h,write_to_dev},
-                 {log,"fourth"}, {trace,logger_std_h,write_to_dev},
-                 {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
-
-    dbg:stop_clear(),
-
-    %% verify that filesync has been performed as expected
-    Received1 = lists:map(fun({trace,M,F,_}) -> {trace,M,F};
-                             (Other) -> Other
-                          end, test_server:messages_get()),
-    ct:pal("Trace #1 =~n~p", [Received1]),
-    Received1 = Expected1 ++ Expected2 ++ Expected3,
-
-    try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\n">>}, 1000),
-    
-    {ok,_} = dbg:tracer(process, {TraceFun, Tester}),
-    {ok,_} = dbg:p(whereis(?MODULE), [c]),
-    {ok,_} = dbg:tpl(logger_std_h, handle_cast, 2, []),
+    check_tracer(?IDLE_DETECT_TIME_MSEC*2),
 
     %% switch repeated filesync on and verify that the looping works
     SyncInt = 1000,
     WaitT = 4500,
+    OneSync = {logger_std_h,handle_cast,repeated_filesync},
+    %% receive 1 initial repeated_filesync, then 1 per sec
+    start_tracer([{logger_std_h,handle_cast,2}],
+                 [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+
     logger:set_handler_config(?MODULE, logger_std_h,
                               #{filesync_repeat_interval => SyncInt}),
     SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)),
     timer:sleep(WaitT),
     logger:set_handler_config(?MODULE, logger_std_h,
-                              #{filesync_repeat_interval => no_repeat}),    
-    dbg:stop_clear(),
-
-    Received2 = lists:map(fun({trace,_M,handle_cast,[{Op,_},_]}) -> {trace,Op};
-                             (Other) -> Other
-                          end, test_server:messages_get()),
-    ct:pal("Trace #2 =~n~p", [Received2]),
-    OneSync = [{trace,repeated_filesync}],
-    %% receive 1 initial repeated_filesync, then 1 per sec
-    Received2 =
-        lists:flatten([OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+                              #{filesync_repeat_interval => no_repeat}),
+    check_tracer(100),
     ok.
 filesync(cleanup, _Config) ->
+    dbg:stop_clear(),
     logger:remove_handler(?MODULE).
 
 write_failure(Config) ->
@@ -785,7 +778,7 @@ op_switch_to_drop_tty(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 op_switch_to_flush_file() ->
-    [{timetrap,{seconds,60}}].
+    [{timetrap,{minutes,3}}].
 op_switch_to_flush_file(Config) ->
     {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
 
@@ -1052,7 +1045,7 @@ restart_after(cleanup, _Config) ->
 %% during high load to verify that sync, dropping and flushing is
 %% handled correctly.
 handler_requests_under_load() ->
-    [{timetrap,{seconds,60}}].
+    [{timetrap,{minutes,3}}].
 handler_requests_under_load(Config) ->
     {Log,HConfig,StdHConfig} =
         start_handler(?MODULE, ?FUNCTION_NAME, Config),
@@ -1394,3 +1387,67 @@ analyse(Msgs) ->
             From ! {result,self(),TestFun(Msgs)},
             analyse(Msgs)
     end.
+
+start_tracer(Trace,Expected) ->
+    Pid = self(),
+    FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)),
+    dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
+    dbg:p(whereis(?MODULE),[c]),
+    dbg:p(FileCtrlPid,[c]),
+    tpl(Trace),
+    ok.
+
+tpl([{M,F,A}|Trace]) ->
+    {ok,Match} = dbg:tpl(M,F,A,[]),
+    case lists:keyfind(matched,1,Match) of
+        {_,_,1} ->
+            ok;
+        _ ->
+            dbg:stop_clear(),
+            throw({skip,"Can't trace "++atom_to_list(M)++":"++
+                       atom_to_list(F)++"/"++integer_to_list(A)})
+    end,
+    tpl(Trace);
+tpl([]) ->
+    ok.
+
+tracer({trace,_,call,{logger_std_h,handle_cast,[{Op,_}|_]}},
+       {Pid,[{Mod,Func,Op}|Expected]}) ->
+    maybe_tracer_done(Pid,Expected,{Mod,Func,Op});
+tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}},
+       {Pid,[{Mod,Func,Data}|Expected]}) ->
+    maybe_tracer_done(Pid,Expected,{Mod,Func,Data});
+tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) ->
+    maybe_tracer_done(Pid,Expected,{Mod,Func});
+tracer({trace,_,call,Call}, {Pid,Expected}) ->
+    ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]),
+    Pid ! {tracer_got_unexpected,Call,Expected},
+    {Pid,Expected}.
+
+maybe_tracer_done(Pid,[]=Expected,Got) ->
+    ct:log("Tracer got: ~p~n",[Got]),
+    Pid ! {tracer_done,0},
+    {Pid,Expected};
+maybe_tracer_done(Pid,[{no_more,T}]=Expected,Got) ->
+    ct:log("Tracer got: ~p~n",[Got]),
+    Pid ! {tracer_done,T},
+    {Pid,Expected};
+maybe_tracer_done(Pid,Expected,Got) ->
+    ct:log("Tracer got: ~p~n",[Got]),
+    {Pid,Expected}.
+
+check_tracer(T) ->
+    check_tracer(T,fun() -> ct:fail({timeout,tracer}) end).
+check_tracer(T,TimeoutFun) ->
+    receive
+        {tracer_done,Delay} ->
+            %% Possibly wait Delay ms to check that no unexpected
+            %% traces are received
+            check_tracer(Delay,fun() -> ok end);
+        {tracer_got_unexpected,Got,Expected} ->
+            dbg:stop_clear(),
+            ct:fail({tracer_got_unexpected,Got,Expected})
+    after T ->
+            dbg:stop_clear(),
+            TimeoutFun()
+    end.