1%%
2%% %CopyrightBegin%
3%%
4%% Copyright Ericsson AB 2018-2020. All Rights Reserved.
5%%
6%% Licensed under the Apache License, Version 2.0 (the "License");
7%% you may not use this file except in compliance with the License.
8%% You may obtain a copy of the License at
9%%
10%%     http://www.apache.org/licenses/LICENSE-2.0
11%%
12%% Unless required by applicable law or agreed to in writing, software
13%% distributed under the License is distributed on an "AS IS" BASIS,
14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15%% See the License for the specific language governing permissions and
16%% limitations under the License.
17%%
18%% %CopyrightEnd%
19%%
20-module(logger_SUITE).
21
22-compile(export_all).
23
24-include_lib("common_test/include/ct.hrl").
25-include_lib("kernel/include/logger.hrl").
26-include_lib("kernel/src/logger_internal.hrl").
27
28-define(str,"Log from "++atom_to_list(?FUNCTION_NAME)++
29            ":"++integer_to_list(?LINE)).
30-define(map_rep,#{function=>?FUNCTION_NAME, line=>?LINE}).
31-define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]).
32
33-define(MY_LOC(N),#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY},
34                    file=>?FILE, line=>?LINE-N}).
35
36-define(TRY(X), my_try(fun() -> X end)).
37
38
39suite() ->
40    [{timetrap,{seconds,30}},
41     {ct_hooks,[logger_test_lib]}].
42
43init_per_suite(Config) ->
44    case logger:get_handler_config(?STANDARD_HANDLER) of
45        {ok,StdH} ->
46            ok = logger:remove_handler(?STANDARD_HANDLER),
47            [{default_handler,StdH}|Config];
48        _ ->
49            Config
50    end.
51
52end_per_suite(Config) ->
53    case ?config(default_handler,Config) of
54        #{module:=HMod} = HConfig ->
55            ok = logger:add_handler(?STANDARD_HANDLER,HMod,HConfig);
56        _ ->
57            ok
58    end.
59
60init_per_group(_Group, Config) ->
61    Config.
62
63end_per_group(_Group, _Config) ->
64    ok.
65
66init_per_testcase(_TestCase, Config) ->
67    PC = logger:get_primary_config(),
68    [{logger_config,PC}|Config].
69
70end_per_testcase(Case, Config) ->
71    try erlang:apply(?MODULE,Case,[cleanup,Config])
72    catch error:undef -> ok
73    end,
74    ok.
75
76groups() ->
77    [].
78
79all() ->
80    [start_stop,
81     add_remove_handler,
82     multiple_handlers,
83     add_remove_filter,
84     change_config,
85     set_formatter,
86     log_no_levels,
87     log_all_levels_api,
88     macros,
89     set_level,
90     set_module_level,
91     set_application_level,
92     cache_module_level,
93     format_report,
94     filter_failed,
95     handler_failed,
96     config_sanity_check,
97     log_failed,
98     emulator,
99     via_logger_process,
100     other_node,
101     compare_levels,
102     process_metadata,
103     app_config,
104     kernel_config,
105     pretty_print].
106
107start_stop(_Config) ->
108    S = whereis(logger),
109    true = is_pid(S),
110    ok.
111
112add_remove_handler(_Config) ->
113    register(callback_receiver,self()),
114    Hs0 = logger:get_handler_config(),
115    {error,{not_found,h1}} = logger:get_handler_config(h1),
116    ok = logger:add_handler(h1,?MODULE,#{}),
117    [add] = test_server:messages_get(),
118    Hs = logger:get_handler_config(),
119    Hs0 = lists:filter(fun(#{id:=h1}) -> false; (_) -> true end, Hs),
120    {ok,#{module:=?MODULE,level:=all,filters:=[],filter_default:=log}} = %defaults
121        logger:get_handler_config(h1),
122    ok = logger:set_handler_config(h1,filter_default,stop),
123    [changing_config] = test_server:messages_get(),
124    ?LOG_NOTICE("hello",[]),
125    ok = check_no_log(),
126    ok = logger:set_handler_config(h1,filter_default,log),
127    [changing_config] = test_server:messages_get(),
128    {ok,#{filter_default:=log}} = logger:get_handler_config(h1),
129    ?LOG_NOTICE("hello",[]),
130    ok = check_logged(notice,"hello",[],?MY_LOC(1)),
131    ok = logger:remove_handler(h1),
132    [remove] = test_server:messages_get(),
133    Hs0 = logger:get_handler_config(),
134    {error,{not_found,h1}} = logger:get_handler_config(h1),
135    {error,{not_found,h1}} = logger:remove_handler(h1),
136    logger:notice("hello",[]),
137    ok = check_no_log(),
138    ok.
139
140add_remove_handler(cleanup,_Config) ->
141    logger:remove_handler(h1),
142    ok.
143
144multiple_handlers(_Config) ->
145    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
146    ok = logger:add_handler(h2,?MODULE,#{level=>error,filter_default=>log}),
147    ?LOG_ERROR("hello",[]),
148    ok = check_logged(error,"hello",[],?MY_LOC(1)),
149    ok = check_logged(error,"hello",[],?MY_LOC(2)),
150    ?LOG_NOTICE("hello",[]),
151    ok = check_logged(notice,"hello",[],?MY_LOC(1)),
152    ok = check_no_log(),
153    ok.
154
155multiple_handlers(cleanup,_Config) ->
156    logger:remove_handler(h1),
157    logger:remove_handler(h2),
158    ok.
159
160add_remove_filter(_Config) ->
161    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
162    LF = {fun(Log,_) -> Log#{level=>error} end, []},
163    ok = logger:add_primary_filter(lf,LF),
164    {error,{already_exist,lf}} = logger:add_primary_filter(lf,LF),
165    {error,{already_exist,lf}} = logger:add_primary_filter(lf,{fun(Log,_) ->
166                                                                       Log
167                                                               end, []}),
168    ?LOG_NOTICE("hello",[]),
169    ok = check_logged(error,"hello",[],?MY_LOC(1)),
170    ok = check_no_log(),
171
172    ok = logger:add_handler(h2,?MODULE,#{level=>notice,filter_default=>log}),
173    HF = {fun(#{level:=error}=Log,_) ->
174                  Log#{level=>mylevel};
175             (_,_) ->
176                  ignore
177          end,
178          []},
179    ok = logger:add_handler_filter(h1,hf,HF),
180    {error,{already_exist,hf}} = logger:add_handler_filter(h1,hf,HF),
181    {error,{already_exist,hf}} = logger:add_handler_filter(h1,hf,{fun(Log,_) ->
182                                                                          Log
183                                                                  end, []}),
184    ?LOG_NOTICE("hello",[]),
185    ok = check_logged(mylevel,"hello",[],?MY_LOC(1)),
186    ok = check_logged(error,"hello",[],?MY_LOC(2)),
187
188    ok = logger:remove_primary_filter(lf),
189    {error,{not_found,lf}} = logger:remove_primary_filter(lf),
190
191    ?LOG_NOTICE("hello",[]),
192    ok = check_logged(notice,"hello",[],?MY_LOC(1)),
193    ok = check_logged(notice,"hello",[],?MY_LOC(2)),
194
195    ?LOG_ERROR("hello",[]),
196    ok = check_logged(mylevel,"hello",[],?MY_LOC(1)),
197    ok = check_logged(error,"hello",[],?MY_LOC(2)),
198
199    ok = logger:remove_handler_filter(h1,hf),
200    {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf),
201    ?LOG_NOTICE("hello",[]),
202    ok = check_logged(notice,"hello",[],?MY_LOC(1)),
203    ok = check_logged(notice,"hello",[],?MY_LOC(2)),
204
205    ?LOG_ERROR("hello",[]),
206    ok = check_logged(error,"hello",[],?MY_LOC(1)),
207    ok = check_logged(error,"hello",[],?MY_LOC(2)),
208    ok.
209
210add_remove_filter(cleanup,_Config) ->
211    logger:remove_primary_filter(lf),
212    logger:remove_handler(h1),
213    logger:remove_handler(h2),
214    ok.
215
216change_config(_Config) ->
217    %% Overwrite handler config - check that defaults are added
218    {error,{not_found,h1}} = logger:set_handler_config(h1,#{}),
219    ok = logger:add_handler(h1,?MODULE,#{level=>notice,custom=>custom}),
220    {ok,#{module:=?MODULE,level:=notice,filter_default:=log,custom:=custom}} =
221        logger:get_handler_config(h1),
222    register(callback_receiver,self()),
223    ok = logger:set_handler_config(h1,#{filter_default=>stop}),
224    [changing_config] = test_server:messages_get(),
225    {ok,#{module:=?MODULE,level:=all,filter_default:=stop}=C2} =
226        logger:get_handler_config(h1),
227    false = maps:is_key(custom,C2),
228    {error,fail} = logger:set_handler_config(h1,#{conf_call=>fun() -> {error,fail} end}),
229    {error,{attempting_syncronous_call_to_self,_}} =
230        logger:set_handler_config(
231          h1,#{conf_call=>fun() -> logger:set_handler_config(?MODULE,#{}) end}),
232    ok =
233        logger:set_handler_config(
234          h1,#{conf_call=>fun() -> logger:set_module_level(?MODULE,debug) end}),
235    {ok,C2} = logger:get_handler_config(h1),
236
237    %% Change handler config: Single key
238    {error,fail} = logger:set_handler_config(h1,conf_call,fun() -> {error,fail} end),
239    ok = logger:set_handler_config(h1,custom,custom),
240    [changing_config] = test_server:messages_get(),
241    {ok,#{custom:=custom}=C3} = logger:get_handler_config(h1),
242    C2 = maps:remove(custom,C3),
243
244    %% Change handler config: Map
245    ok = logger:update_handler_config(h1,#{custom=>new_custom}),
246    [changing_config] = test_server:messages_get(),
247    {ok,C4} = logger:get_handler_config(h1),
248    C4 = C3#{custom:=new_custom},
249
250    %% Change handler config: Id and module can not be changed
251    {error,{illegal_config_change,Old,New}} =
252        logger:set_handler_config(h1,id,newid),
253    %% Check that only the faulty field is included in return
254    [{id,h1}] = maps:to_list(Old),
255    [{id,newid}] = maps:to_list(New),
256    %% Check that both fields are included when both are changed
257    {error,{illegal_config_change,
258            #{id:=h1,module:=?MODULE},
259            #{id:=newid,module:=newmodule}}} =
260        logger:set_handler_config(h1,#{id=>newid,module=>newmodule}),
261
262    %% Change primary config: Single key
263    PConfig0 = logger:get_primary_config(),
264    ok = logger:set_primary_config(level,warning),
265    PConfig1 = logger:get_primary_config(),
266    PConfig1 = PConfig0#{level:=warning},
267
268    %% Change primary config: Map
269    ok = logger:update_primary_config(#{level=>error}),
270    PConfig2 = logger:get_primary_config(),
271    PConfig2 = PConfig1#{level:=error},
272
273    %% Overwrite primary config - check that defaults are added
274    ok = logger:set_primary_config(#{filter_default=>stop}),
275    #{level:=notice,filters:=[],filter_default:=stop}=PC1 =
276        logger:get_primary_config(),
277    4 = maps:size(PC1),
278    %% Check that internal 'handlers' field has not been changed
279    MS = [{{{?HANDLER_KEY,'$1'},'_'},[],['$1']}],
280    HIds1 = lists:sort(ets:select(?LOGGER_TABLE,MS)), % dirty, internal data
281    HIds2 = lists:sort(logger:get_handler_ids()),
282    HIds1 = HIds2,
283
284    %% Cleanup
285    ok = logger:set_primary_config(PConfig0),
286    [] = test_server:messages_get(),
287
288    ok.
289
290change_config(cleanup,Config) ->
291    logger:remove_handler(h1),
292    PC = ?config(logger_config,Config),
293    logger:set_primary_config(PC),
294    ok.
295
296set_formatter(_Config) ->
297    {error,{not_found,h1}}=logger:set_handler_config(h1,formatter,{?MODULE,[]}),
298    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
299    ok = logger:set_handler_config(h1,formatter,{?MODULE,[]}),
300    logger:notice("hello",[]),
301    receive
302        {_Log,#{formatter:={?MODULE,[]}}} ->
303            ok
304    after 500 ->
305            ct:fail({timeout,no_log,process_info(self(),messages)})
306    end,
307    ok.
308
309set_formatter(cleanup,_Config) ->
310    logger:remove_handler(h1),
311    ok.
312
313log_no_levels(_Config) ->
314    ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}),
315    logger:notice(M1=?map_rep),
316    ok = check_logged(notice,M1,#{}),
317
318    Levels = [emergency,alert,critical,error,warning,notice,info,debug],
319    ok = logger:set_primary_config(level,none),
320    [logger:Level(#{Level=>rep}) || Level <- Levels],
321    ok = check_no_log(),
322
323    ok = logger:set_primary_config(level,all),
324    M2 = ?map_rep,
325    ?LOG_NOTICE(M2),
326    ok = check_logged(notice,M2,#{}),
327
328    ok = logger:set_module_level(?MODULE,none),
329    ?LOG_EMERGENCY(?map_rep),
330    ?LOG_ALERT(?map_rep),
331    ?LOG_CRITICAL(?map_rep),
332    ?LOG_ERROR(?map_rep),
333    ?LOG_WARNING(?map_rep),
334    ?LOG_NOTICE(?map_rep),
335    ?LOG_INFO(?map_rep),
336    ?LOG_DEBUG(?map_rep),
337    ok = check_no_log(),
338
339    ok = logger:unset_module_level(?MODULE),
340    logger:notice(M3=?map_rep),
341    ok = check_logged(notice,M3,#{}),
342
343    ok = logger:set_handler_config(h1,level,none),
344    [logger:Level(#{Level=>rep}) || Level <- Levels],
345    ok = check_no_log(),
346
347    ok.
348log_no_levels(cleanup,_Config) ->
349    logger:remove_handler(h1),
350    logger:set_primary_config(level,notice),
351    logger:unset_module_level(?MODULE),
352    ok.
353
354log_all_levels_api(_Config) ->
355    ok = logger:set_primary_config(level,all),
356    ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}),
357    test_api(emergency),
358    test_api(alert),
359    test_api(critical),
360    test_api(error),
361    test_api(warning),
362    test_api(notice),
363    test_api(info),
364    test_api(debug),
365    test_log_function(emergency),
366    ok.
367
368log_all_levels_api(cleanup,_Config) ->
369    logger:remove_handler(h1),
370    logger:set_primary_config(level,notice),
371    ok.
372
373macros(_Config) ->
374    ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}),
375    test_macros(emergency),
376    test_log_macro(alert),
377    ok.
378
379macros(cleanup,_Config) ->
380    logger:remove_handler(h1),
381    logger:unset_module_level(?MODULE),
382    ok.
383
384set_level(_Config) ->
385    ok = logger:add_handler(h1,?MODULE,#{level=>all,filter_default=>log}),
386    logger:debug(?map_rep),
387    ok = check_no_log(),
388    logger:notice(M1=?map_rep),
389    ok = check_logged(notice,M1,#{}),
390    ok = logger:set_primary_config(level,debug),
391    logger:debug(M2=?map_rep),
392    ok = check_logged(debug,M2,#{}),
393    ok.
394
395set_level(cleanup,_Config) ->
396    logger:remove_handler(h1),
397    logger:set_primary_config(level,notice),
398    ok.
399
400set_module_level(_Config) ->
401    [] = logger:get_module_level([?MODULE,other]),
402    [] = logger:get_module_level(?MODULE),
403    [] = logger:get_module_level(),
404
405    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
406    {error,{invalid_level,bad}} = logger:set_module_level(?MODULE,bad),
407    {error,{not_a_list_of_modules,{bad}}} =
408        logger:set_module_level({bad},warning),
409    {error,{not_a_list_of_modules,[{bad}]}} =
410        logger:set_module_level([{bad}],warning),
411    ok = logger:set_module_level(?MODULE,warning),
412    [{?MODULE,warning}] = logger:get_module_level([?MODULE,other]),
413    [{?MODULE,warning}] = logger:get_module_level(?MODULE),
414    [{?MODULE,warning}] = logger:get_module_level(),
415    logger:notice(?map_rep,?MY_LOC(0)),
416    ok = check_no_log(),
417    logger:warning(M1=?map_rep,?MY_LOC(0)),
418    ok = check_logged(warning,M1,?MY_LOC(1)),
419    ok = logger:set_module_level(?MODULE,notice),
420    [{?MODULE,notice}] = logger:get_module_level([?MODULE,other]),
421    [{?MODULE,notice}] = logger:get_module_level(?MODULE),
422    [{?MODULE,notice}] = logger:get_module_level(),
423    logger:notice(M2=?map_rep,?MY_LOC(0)),
424    ok = check_logged(notice,M2,?MY_LOC(1)),
425
426    {error,{not_a_list_of_modules,{bad}}} = logger:unset_module_level({bad}),
427    {error,{not_a_list_of_modules,[{bad}]}} = logger:unset_module_level([{bad}]),
428    ok = logger:unset_module_level(?MODULE),
429    [] = logger:get_module_level([?MODULE,other]),
430    [] = logger:get_module_level(?MODULE),
431    [] = logger:get_module_level(),
432
433    ok = logger:set_module_level([m1,m2,m3],notice),
434    [{m1,notice},{m2,notice},{m3,notice}] = logger:get_module_level(),
435    ok = logger:unset_module_level(m2),
436    [{m1,notice},{m3,notice}] = logger:get_module_level(),
437    ok = logger:unset_module_level(),
438    [] = logger:get_module_level(),
439
440    ok.
441
442set_module_level(cleanup,_Config) ->
443    logger:remove_handler(h1),
444    logger:unset_module_level(?MODULE),
445    ok.
446
447set_application_level(_Config) ->
448
449    {error,{not_loaded,mnesia}} = logger:set_application_level(mnesia, warning),
450    {error,{not_loaded,mnesia}} = logger:unset_application_level(mnesia),
451
452    case application:load(mnesia) of
453        ok ->
454            {ok, Modules} = application:get_key(mnesia, modules),
455            [] = logger:get_module_level(Modules),
456
457            {error,{invalid_level,warn}} =
458                logger:set_application_level(mnesia, warn),
459
460            ok = logger:set_application_level(mnesia, debug),
461            DebugModules = lists:sort([{M,debug} || M <- Modules]),
462            DebugModules = lists:sort(logger:get_module_level(Modules)),
463
464            ok = logger:set_application_level(mnesia, warning),
465
466            WarnModules = lists:sort([{M,warning} || M <- Modules]),
467            WarnModules = lists:sort(logger:get_module_level(Modules)),
468
469            ok = logger:unset_application_level(mnesia),
470            [] = logger:get_module_level(Modules);
471        {error,{"no such file or directory","mnesia.app"}} ->
472            {skip, "Cannot load mnesia, does not exist"}
473    end.
474
475set_application_level(cleanup,_Config) ->
476    _ = logger:unset_application_level(mnesia),
477    _ = application:unload(mnesia),
478    ok.
479
480cache_module_level(_Config) ->
481
482    %% This test does a lot of whitebox tests so be prepared for that
483    persistent_term:erase({logger_config,?MODULE}),
484
485    primary = persistent_term:get({logger_config,?MODULE}, primary),
486    ?LOG_NOTICE(?map_rep),
487    5 = persistent_term:get({logger_config,?MODULE}, primary),
488    logger:set_primary_config(level, info),
489    6 = persistent_term:get({logger_config,?MODULE}, primary),
490    ok.
491
492cache_module_level(cleanup,_Config) ->
493    logger:unset_module_level(?MODULE),
494    ok.
495
496format_report(_Config) ->
497    {"~ts",["string"]} = logger:format_report("string"),
498    {"~tp",[term]} = logger:format_report(term),
499    {"~tp",[[]]} = logger:format_report([]),
500    {"    ~tp: ~tp",[key,value]} = logger:format_report([{key,value}]),
501    KeyVals = [{key1,value1},{key2,"value2"},{key3,[]}],
502    KeyValRes =
503        {"    ~tp: ~tp\n    ~tp: ~ts\n    ~tp: ~tp",
504         [key1,value1,key2,"value2",key3,[]]} =
505        logger:format_report(KeyVals),
506    KeyValRes = logger:format_report(maps:from_list(KeyVals)),
507    KeyValRes = logger:format_otp_report(#{label=>{?MODULE,test},report=>KeyVals}),
508    {"    ~tp: ~tp\n    ~tp: ~tp",
509     [label,{?MODULE,test},report,KeyVals]} =
510        logger:format_report(#{label=>{?MODULE,test},report=>KeyVals}),
511
512    {"    ~tp: ~tp\n    ~tp",[key1,value1,term]} =
513        logger:format_report([{key1,value1},term]),
514
515    {"    ~tp: ~tp\n    ~tp",[key1,value1,[]]} =
516        logger:format_report([{key1,value1},[]]),
517
518    {"~tp",[[]]} = logger:format_report([[],[],[]]),
519
520    ok.
521
522filter_failed(_Config) ->
523    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
524
525    %% Logger filters
526    {error,{invalid_filter,_}} =
527        logger:add_primary_filter(lf,{fun(_) -> ok end,args}),
528    ok = logger:add_primary_filter(lf,
529                                   {fun(_,_) ->
530                                            erlang:error({badmatch,b})
531                                    end,
532                                    args}),
533    #{filters:=[_]} = logger:get_primary_config(),
534    ok = logger:notice(M1=?map_rep),
535    ok = check_logged(notice,M1,#{}),
536    {error,{not_found,lf}} = logger:remove_primary_filter(lf),
537
538    ok = logger:add_primary_filter(lf,{fun(_,_) -> faulty_return end,args}),
539    #{filters:=[_]} = logger:get_primary_config(),
540    ok = logger:notice(M2=?map_rep),
541    ok = check_logged(notice,M2,#{}),
542    {error,{not_found,lf}} = logger:remove_primary_filter(lf),
543
544    %% Handler filters
545    {error,{not_found,h0}} =
546        logger:add_handler_filter(h0,hf,{fun(_,_) -> ignore end,args}),
547    {error,{not_found,h0}} = logger:remove_handler_filter(h0,hf),
548    {error,{invalid_filter,_}} =
549        logger:add_handler_filter(h1,hf,{fun(_) -> ok end,args}),
550    ok = logger:add_handler_filter(h1,hf,
551                                   {fun(_,_) ->
552                                            erlang:error({badmatch,b})
553                                    end,
554                                    args}),
555    {ok,#{filters:=[_]}} = logger:get_handler_config(h1),
556    ok = logger:notice(M3=?map_rep),
557    ok = check_logged(notice,M3,#{}),
558    {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf),
559
560    ok = logger:add_handler_filter(h1,hf,{fun(_,_) -> faulty_return end,args}),
561    {ok,#{filters:=[_]}} = logger:get_handler_config(h1),
562    ok = logger:notice(M4=?map_rep),
563    ok = check_logged(notice,M4,#{}),
564    {error,{not_found,hf}} = logger:remove_handler_filter(h1,hf),
565
566    ok.
567
568filter_failed(cleanup,_Config) ->
569    logger:remove_handler(h1),
570    ok.
571
572handler_failed(_Config) ->
573    logger:set_primary_config(level,all),
574    register(callback_receiver,self()),
575    {error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}),
576    {error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}),
577    {error,{invalid_config,bad}} = logger:add_handler(h1,?MODULE,bad),
578    {error,{invalid_filters,false}} =
579        logger:add_handler(h1,?MODULE,#{filters=>false}),
580    {error,{invalid_filter_default,true}} =
581        logger:add_handler(h1,?MODULE,#{filter_default=>true}),
582    {error,{invalid_formatter,[]}} =
583        logger:add_handler(h1,?MODULE,#{formatter=>[]}),
584    {error,{invalid_handler,_}} = logger:add_handler(h1,nomodule,#{filter_default=>log}),
585    logger:notice(?map_rep),
586    check_no_log(),
587    H1 = logger:get_handler_config(),
588    false = lists:search(fun(#{id:=h1}) -> true; (_) -> false end,H1),
589    {error,{not_found,h1}} = logger:remove_handler(h1),
590
591    ok = logger:add_handler(h2,?MODULE,
592                            #{filter_default => log,
593                              log_call => fun() ->
594                                                  erlang:error({badmatch,b})
595                                          end}),
596    {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}),
597    [add] = test_server:messages_get(),
598
599    logger:notice(?map_rep),
600    [remove] = test_server:messages_get(),
601    H2 = logger:get_handler_config(),
602    false = lists:search(fun(#{id:=h2}) -> true; (_) -> false end,H2),
603    {error,{not_found,h2}} = logger:remove_handler(h2),
604
605    CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end,
606    CrashHandler = fun() -> erlang:error({badmatch,b}) end,
607    KillHandler = fun() -> exit(self(), die) end,
608
609    {error,{handler_not_added,{attempting_syncronous_call_to_self,_}}} =
610        logger:add_handler(h1,?MODULE,#{add_call=>CallAddHandler}),
611    {error,{handler_not_added,{callback_crashed,_}}} =
612        logger:add_handler(h1,?MODULE,#{add_call=>CrashHandler}),
613    {error,{handler_not_added,{logger_process_exited,_,die}}} =
614        logger:add_handler(h1,?MODULE,#{add_call=>KillHandler}),
615
616    check_no_log(),
617    ok = logger:add_handler(h1,?MODULE,#{tc_proc=>self()}),
618    {error,{attempting_syncronous_call_to_self,_}} =
619        logger:set_handler_config(h1,#{conf_call=>CallAddHandler}),
620    {error,{callback_crashed,_}} =
621        logger:set_handler_config(h1,#{conf_call=>CrashHandler}),
622    {error,{logger_process_exited,_,die}} =
623        logger:set_handler_config(h1,#{conf_call=>KillHandler}),
624
625    {error,{attempting_syncronous_call_to_self,_}} =
626        logger:set_handler_config(h1,conf_call,CallAddHandler),
627    {error,{callback_crashed,_}} =
628        logger:set_handler_config(h1,conf_call,CrashHandler),
629    {error,{logger_process_exited,_,die}} =
630        logger:set_handler_config(h1,conf_call,KillHandler),
631
632    ok = logger:remove_handler(h1),
633    [add,{#{level:=error},_},{#{level:=error},_},
634     {#{level:=error},_},{#{level:=error},_},remove] = test_server:messages_get(),
635
636    check_no_log(),
637    ok = logger:add_handler(h1,?MODULE,#{rem_call=>CallAddHandler}),
638    ok = logger:remove_handler(h1),
639    ok = logger:add_handler(h1,?MODULE,#{rem_call=>CrashHandler}),
640    ok = logger:remove_handler(h1),
641    ok = logger:add_handler(h1,?MODULE,#{rem_call=>KillHandler}),
642    ok = logger:remove_handler(h1),
643    [add,add,add] = test_server:messages_get(),
644
645    ok.
646
647handler_failed(cleanup,_Config) ->
648    logger:remove_handler(h1),
649    logger:remove_handler(h2),
650    logger:set_primary_config(level,info),
651    ok.
652
653config_sanity_check(_Config) ->
654    %% Primary config
655    {error,{invalid_config,bad}} = logger:set_primary_config(bad),
656    {error,{invalid_filter_default,bad}} =
657        logger:set_primary_config(filter_default,bad),
658    {error,{invalid_level,bad}} = logger:set_primary_config(level,bad),
659    {error,{invalid_filters,bad}} = logger:set_primary_config(filters,bad),
660    {error,{invalid_filter,bad}} = logger:set_primary_config(filters,[bad]),
661    {error,{invalid_filter,{_,_}}} =
662        logger:set_primary_config(filters,[{id,bad}]),
663    {error,{invalid_filter,{_,{_,_}}}} =
664        logger:set_primary_config(filters,[{id,{bad,args}}]),
665    {error,{invalid_filter,{_,{_,_}}}} =
666        logger:set_primary_config(filters,[{id,{fun() -> ok end,args}}]),
667    {error,{invalid_primary_config,{bad,bad}}} =
668        logger:set_primary_config(bad,bad),
669
670    %% Handler config
671    {error,{not_found,h1}} = logger:set_handler_config(h1,a,b),
672    ok = logger:add_handler(h1,?MODULE,#{}),
673    {error,{invalid_filter_default,bad}} =
674        logger:set_handler_config(h1,filter_default,bad),
675    {error,{invalid_level,bad}} = logger:set_handler_config(h1,level,bad),
676    {error,{invalid_filters,bad}} = logger:set_handler_config(h1,filters,bad),
677    {error,{invalid_filter,bad}} = logger:set_handler_config(h1,filters,[bad]),
678    {error,{invalid_filter,{_,_}}} =
679        logger:set_handler_config(h1,filters,[{id,bad}]),
680    {error,{invalid_filter,{_,{_,_}}}} =
681        logger:set_handler_config(h1,filters,[{id,{bad,args}}]),
682    {error,{invalid_filter,{_,{_,_}}}} =
683        logger:set_handler_config(h1,filters,[{id,{fun() -> ok end,args}}]),
684    {error,{invalid_formatter,bad}} =
685        logger:set_handler_config(h1,formatter,bad),
686    {error,{invalid_module,{bad}}} =
687        logger:set_handler_config(h1,formatter,{{bad},cfg}),
688    {error,{invalid_formatter_config,logger_formatter,bad}} =
689        logger:set_handler_config(h1,formatter,{logger_formatter,bad}),
690    {error,{invalid_formatter_config,logger_formatter,{bad,bad}}} =
691        logger:set_handler_config(h1,formatter,{logger_formatter,#{bad=>bad}}),
692    {error,{invalid_formatter_template,logger_formatter,bad}} =
693        logger:set_handler_config(h1,formatter,{logger_formatter,
694                                                #{template=>bad}}),
695    {error,{invalid_formatter_template,logger_formatter,[1]}} =
696        logger:set_handler_config(h1,formatter,{logger_formatter,
697                                                #{template=>[1]}}),
698    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
699                                                 #{template=>[]}}),
700    {error,{invalid_formatter_config,logger_formatter,{single_line,bad}}} =
701        logger:set_handler_config(h1,formatter,{logger_formatter,
702                                                #{single_line=>bad}}),
703    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
704                                                 #{single_line=>true}}),
705    {error,{invalid_formatter_config,logger_formatter,{legacy_header,bad}}} =
706        logger:set_handler_config(h1,formatter,{logger_formatter,
707                                                #{legacy_header=>bad}}),
708    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
709                                                 #{legacy_header=>true}}),
710    {error,{invalid_formatter_config,logger_formatter,{report_cb,bad}}} =
711        logger:set_handler_config(h1,formatter,{logger_formatter,
712                                                #{report_cb=>bad}}),
713    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
714                                                 #{report_cb=>fun(R) ->
715                                                                      {"~p",[R]}
716                                                              end}}),
717    {error,{invalid_formatter_config,logger_formatter,{chars_limit,bad}}} =
718        logger:set_handler_config(h1,formatter,{logger_formatter,
719                                                #{chars_limit=>bad}}),
720    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
721                                                 #{chars_limit=>unlimited}}),
722    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
723                                                 #{chars_limit=>4}}),
724    {error,{invalid_formatter_config,logger_formatter,{depth,bad}}} =
725        logger:set_handler_config(h1,formatter,{logger_formatter,
726                                                #{depth=>bad}}),
727    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
728                                                 #{depth=>unlimited}}),
729    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
730                                                 #{depth=>4}}),
731    {error,{invalid_formatter_config,logger_formatter,{max_size,bad}}} =
732        logger:set_handler_config(h1,formatter,{logger_formatter,
733                                                #{max_size=>bad}}),
734    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
735                                                 #{max_size=>unlimited}}),
736    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
737                                                 #{max_size=>4}}),
738    ok = logger:set_handler_config(h1,formatter,{module,config}),
739    {error,{callback_crashed,{error,{badmatch,3},[{?MODULE,check_config,1,_}]}}} =
740        logger:set_handler_config(h1,formatter,{?MODULE,crash}),
741    ok = logger:set_handler_config(h1,custom,custom),
742
743    %% Old utc parameter is no longer allowed (replaced by time_offset)
744    {error,{invalid_formatter_config,logger_formatter,{utc,true}}} =
745         logger:set_handler_config(h1,formatter,{logger_formatter,
746                                                 #{utc=>true}}),
747    {error,{invalid_formatter_config,logger_formatter,{time_offset,bad}}} =
748        logger:set_handler_config(h1,formatter,{logger_formatter,
749                                                #{time_offset=>bad}}),
750    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
751                                                 #{time_offset=>0}}),
752    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
753                                                 #{time_offset=>""}}),
754    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
755                                                 #{time_offset=>"Z"}}),
756    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
757                                                 #{time_offset=>"z"}}),
758    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
759                                                 #{time_offset=>"-0:0"}}),
760    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
761                                                 #{time_offset=>"+10:13"}}),
762
763    {error,{invalid_formatter_config,logger_formatter,{time_offset,"+0"}}} =
764        logger:set_handler_config(h1,formatter,{logger_formatter,
765                                                #{time_offset=>"+0"}}),
766
767    {error,{invalid_formatter_config,logger_formatter,{time_designator,bad}}} =
768        logger:set_handler_config(h1,formatter,{logger_formatter,
769                                                #{time_designator=>bad}}),
770    {error,{invalid_formatter_config,logger_formatter,{time_designator,"s"}}} =
771        logger:set_handler_config(h1,formatter,{logger_formatter,
772                                                #{time_designator=>"s"}}),
773    {error,{invalid_formatter_config,logger_formatter,{time_designator,0}}} =
774        logger:set_handler_config(h1,formatter,{logger_formatter,
775                                                #{time_designator=>0}}),
776    ok = logger:set_handler_config(h1,formatter,{logger_formatter,
777                                                 #{time_designator=>$\s}}),
778    ok.
779
780config_sanity_check(cleanup,_Config) ->
781    logger:remove_handler(h1),
782    ok.
783
784log_failed(_Config) ->
785    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
786    {error,function_clause} = ?TRY(logger:log(bad,?map_rep)),
787    {error,function_clause} = ?TRY(logger:log(notice,?map_rep,bad)),
788    {error,function_clause} = ?TRY(logger:log(notice,fun() -> ?map_rep end,bad)),
789    {error,function_clause} = ?TRY(logger:log(notice,fun() -> ?map_rep end,bad,#{})),
790    {error,function_clause} = ?TRY(logger:log(notice,bad,bad,bad)),
791    {error,function_clause} = ?TRY(logger:log(notice,bad,bad,#{})),
792    check_no_log(),
793    ok = logger:log(notice,M1=?str,#{}),
794    check_logged(notice,M1,#{}),
795    ok = logger:log(notice,M2=?map_rep,#{}),
796    check_logged(notice,M2,#{}),
797    ok = logger:log(notice,M3=?keyval_rep,#{}),
798    check_logged(notice,M3,#{}),
799
800    %% Should we check report input more thoroughly?
801    ok = logger:log(notice,M4=?keyval_rep++[other,stuff,in,list],#{}),
802    check_logged(notice,M4,#{}),
803
804    %% This might break a handler since it is assumed to be a format
805    %% string and args, so it depends how the handler protects itself
806    %% against something like io_lib:format("ok","ok")
807    ok = logger:log(notice,"ok","ok",#{}),
808    check_logged(notice,"ok","ok",#{}),
809
810    ok.
811
812log_failed(cleanup,_Config) ->
813    logger:remove_handler(h1),
814    ok.
815
816emulator(_Config) ->
817    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log,
818                                         tc_proc=>self()}),
819    Msg = "Error in process ~p on node ~p with exit value:~n~p~n",
820    Error = {badmatch,4},
821    Stack = [{module, function, 2, []}],
822    Pid = spawn(?MODULE, generate_error, [Error, Stack]),
823    check_logged(error, Msg, [Pid, node(), {Error, Stack}],
824                 #{gl=>group_leader(),
825                   error_logger=>#{tag=>error,emulator=>true}}),
826    ok.
827
828emulator(cleanup, _Config) ->
829    logger:remove_handler(h1),
830    ok.
831
832generate_error(Error, Stack) ->
833    erlang:raise(error, Error, Stack).
834
835via_logger_process(Config) ->
836    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log,
837                                         tc_proc=>self()}),
838
839    %% Explicitly send a message to the logger process
840    %% This is used by code_server, erl_prim_loader, init, prim_file, ...
841    Msg = ?str,
842    logger ! {log,error,Msg,[],#{}},
843    check_logged(error, Msg, [], #{}),
844
845    case os:type() of
846        {win32,_} ->
847            %% Skip this part on windows - cant change file mode"
848            ok;
849        _ ->
850            %% This should trigger the same thing from erl_prim_loader
851            Dir = filename:join(?config(priv_dir,Config),"dummydir"),
852            ok = file:make_dir(Dir),
853            ok = file:change_mode(Dir,8#0222),
854            error = erl_prim_loader:list_dir(Dir),
855            check_logged(error,
856                         #{report=>"File operation error: eacces. Target: " ++
857                               Dir ++". Function: list_dir. "},
858                         #{pid=>self(),
859                           gl=>group_leader(),
860                           error_logger=>#{tag=>error_report,
861                                           type=>std_error}}),
862            ok
863    end.
864
865via_logger_process(cleanup, Config) ->
866    Dir = filename:join(?config(priv_dir,Config),"dummydir"),
867    _ = file:change_mode(Dir,8#0664),
868    _ = file:del_dir(Dir),
869    logger:remove_handler(h1),
870    ok.
871
872other_node(_Config) ->
873    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log,
874                                         tc_proc=>self()}),
875    {ok,Node} = test_server:start_node(?FUNCTION_NAME,slave,[]),
876    rpc:call(Node,logger,error,[Msg=?str,#{}]),
877    check_logged(error,Msg,#{}),
878    ok.
879
880other_node(cleanup,_Config) ->
881    Nodes = nodes(),
882    [test_server:stop_node(Node) || Node <- Nodes],
883    logger:remove_handler(h1),
884    ok.
885
886compare_levels(_Config) ->
887    Levels = [none,emergency,alert,critical,error,warning,notice,info,debug,all],
888    ok = compare(Levels),
889    {error,badarg} = ?TRY(logger:compare_levels(bad,bad)),
890    {error,badarg} = ?TRY(logger:compare_levels({bad},notice)),
891    {error,badarg} = ?TRY(logger:compare_levels(notice,"bad")),
892    ok.
893
894compare([L|Rest]) ->
895    eq = logger:compare_levels(L,L),
896    [gt = logger:compare_levels(L,L1) || L1 <- Rest],
897    [lt = logger:compare_levels(L1,L) || L1 <- Rest],
898    compare(Rest);
899compare([]) ->
900    ok.
901
902process_metadata(_Config) ->
903    undefined = logger:get_process_metadata(),
904    {error,badarg} = ?TRY(logger:set_process_metadata(bad)),
905    ok = logger:add_handler(h1,?MODULE,#{level=>notice,filter_default=>log}),
906    Time = logger:timestamp(),
907    ProcMeta = #{time=>Time,line=>0,custom=>proc},
908    ok = logger:set_process_metadata(ProcMeta),
909    S1 = ?str,
910    ?LOG_NOTICE(S1,#{custom=>macro}),
911    check_logged(notice,S1,#{time=>Time,line=>0,custom=>macro}),
912
913    Time2 = logger:timestamp(),
914    S2 = ?str,
915    ?LOG_NOTICE(S2,#{time=>Time2,line=>1,custom=>macro}),
916    check_logged(notice,S2,#{time=>Time2,line=>1,custom=>macro}),
917
918    logger:notice(S3=?str,#{custom=>func}),
919    check_logged(notice,S3,#{time=>Time,line=>0,custom=>func}),
920
921    %% Test that primary metadata is overwritten by process metadata
922    ok = logger:update_primary_config(
923           #{metadata=>#{time=>Time,custom=>global,global=>added,line=>1}}),
924    logger:notice(S4=?str),
925    check_logged(notice,S4,#{time=>Time,line=>0,custom=>proc,global=>added}),
926
927    %% Test that primary metadata is overwritten by func metadata
928    %% and that primary overwrites location metadata.
929    ok = logger:unset_process_metadata(),
930    logger:notice(S5=?str,#{custom=>func}),
931    check_logged(notice,S5,#{time=>Time,line=>1,custom=>func,global=>added}),
932    ok = logger:set_process_metadata(ProcMeta),
933    ok = logger:update_primary_config(#{metadata=>#{}}),
934
935    ProcMeta = logger:get_process_metadata(),
936    ok = logger:update_process_metadata(#{custom=>changed,custom2=>added}),
937    Expected = ProcMeta#{custom:=changed,custom2=>added},
938    Expected = logger:get_process_metadata(),
939    ok = logger:unset_process_metadata(),
940    undefined = logger:get_process_metadata(),
941
942    ok = logger:update_process_metadata(#{custom=>added_again}),
943    {error,badarg} = ?TRY(logger:update_process_metadata(bad)),
944    #{custom:=added_again} = logger:get_process_metadata(),
945
946    ok.
947
948process_metadata(cleanup,_Config) ->
949    logger:remove_handler(h1),
950    ok.
951
952app_config(Config) ->
953    %% Start a node with default configuration
954    {ok,_,Node} = logger_test_lib:setup(Config,[]),
955
956    App1Name = app1,
957    App1 = {application, App1Name,
958            [{description, "Test of app with logger config"},
959             {applications, [kernel]}]},
960    ok = rpc:call(Node,application,load,[App1]),
961    ok = rpc:call(Node,application,set_env,
962                  [App1Name,logger,[{handler,default,logger_std_h,#{}}]]),
963
964    %% Try to add an own default handler
965    {error,{bad_config,{handler,{app1,{already_exist,default}}}}} =
966        rpc:call(Node,logger,add_handlers,[App1Name]),
967
968    %% Add a different handler
969    ok = rpc:call(Node,application,set_env,[App1Name,logger,
970                                            [{handler,myh,logger_std_h,#{}}]]),
971    ok = rpc:call(Node,logger,add_handlers,[App1Name]),
972
973    {ok,#{filters:=DF}} = rpc:call(Node,logger,get_handler_config,[default]),
974    {ok,#{filters:=[]}} = rpc:call(Node,logger,get_handler_config,[myh]),
975
976    true = test_server:stop_node(Node),
977
978    %% Start a node with no default handler, then add an own default handler
979    {ok,#{handlers:=[#{id:=simple}]},Node} =
980        logger_test_lib:setup(Config,[{logger,[{handler,default,undefined}]}]),
981
982    ok = rpc:call(Node,application,load,[App1]),
983    ok = rpc:call(Node,application,set_env,
984                  [App1Name,logger,[{handler,default,logger_std_h,#{}}]]),
985    ok = rpc:call(Node,logger,add_handlers,[App1Name]),
986
987    #{handlers:=[#{id:=default,filters:=DF}]} =
988        rpc:call(Node,logger,get_config,[]),
989
990    true = test_server:stop_node(Node),
991
992    %% Start a silent node, then add an own default handler
993    {ok,#{handlers:=[]},Node} =
994        logger_test_lib:setup(Config,[{error_logger,silent}]),
995
996    {error,{bad_config,{handler,[{some,bad,config}]}}} =
997        rpc:call(Node,logger,add_handlers,[[{some,bad,config}]]),
998    ok = rpc:call(Node,logger,add_handlers,
999                  [[{handler,default,logger_std_h,#{}}]]),
1000
1001    #{handlers:=[#{id:=default,filters:=DF}]} =
1002        rpc:call(Node,logger,get_config,[]),
1003
1004    ok.
1005
1006%% This test case is maintly to see code coverage. Note that
1007%% logger_env_var_SUITE tests a lot of the same, and checks the
1008%% functionality more thoroughly, but since it all happens at node
1009%% start, it is not possible to see code coverage in that test.
1010kernel_config(Config) ->
1011    %% Start a node with simple handler only, then simulate kernel
1012    %% start by calling internally exported
1013    %% internal_init_logger(). This is to test all variants of kernel
1014    %% config, including bad config, and see the code coverage.
1015    {ok,#{handlers:=[#{id:=simple,filters:=DF}]}=LC,Node} =
1016        logger_test_lib:setup(Config,[{error_logger,false}]),
1017
1018    %% Same once more, to get coverage
1019    ok = rpc:call(Node,logger,internal_init_logger,[]),
1020    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1021    LC = rpc:call(Node,logger,get_config,[]),
1022
1023    %% This shall mean the same as above, but using 'logger' parameter
1024    %% instead of 'error_logger'
1025    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1026    ok = rpc:call(Node,application,set_env,
1027                  [kernel,logger,[{handler,default,undefined}]]),
1028    ok = rpc:call(Node,logger,internal_init_logger,[]),
1029    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1030    LC = rpc:call(Node,logger,get_config,[]),
1031
1032    %% Silent
1033    ok = rpc:call(Node,application,unset_env,[kernel,logger]),
1034    ok = rpc:call(Node,application,set_env,[kernel,error_logger,silent]),
1035    ok = rpc:call(Node,logger,internal_init_logger,[]),
1036    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1037    #{primary:=#{filter_default:=log,filters:=[]},
1038      handlers:=[],
1039      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1040
1041    %% Default
1042    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1043    ok = rpc:call(Node,application,unset_env,[kernel,logger]),
1044    ok = rpc:call(Node,logger,internal_init_logger,[]),
1045    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1046    #{primary:=#{filter_default:=log,filters:=[]},
1047      handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}],
1048      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1049
1050    %% error_logger=tty (same as default)
1051    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1052    ok = rpc:call(Node,application,set_env,[kernel,error_logger,tty]),
1053    ok = rpc:call(Node,application,unset_env,[kernel,logger]),
1054    ok = rpc:call(Node,logger,internal_init_logger,[]),
1055    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1056    #{primary:=#{filter_default:=log,filters:=[]},
1057      handlers:=[#{id:=default,filters:=DF,config:=#{type:=standard_io}}],
1058      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1059
1060    %% error_logger={file,File}
1061    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1062    F = filename:join(?config(priv_dir,Config),
1063                      atom_to_list(?FUNCTION_NAME)++".log"),
1064    ok = rpc:call(Node,application,set_env,[kernel,error_logger,{file,F}]),
1065    ok = rpc:call(Node,application,unset_env,[kernel,logger]),
1066    ok = rpc:call(Node,logger,internal_init_logger,[]),
1067    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1068    #{primary:=#{filter_default:=log,filters:=[]},
1069      handlers:=[#{id:=default,filters:=DF,
1070                   config:=#{type:=file,file:=F,modes:=Modes}}],
1071      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1072    [append,delayed_write,raw] = lists:sort(Modes),
1073
1074
1075    %% Same, but using 'logger' parameter instead of 'error_logger'
1076    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1077    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1078    ok = rpc:call(Node,application,set_env,[kernel,logger,
1079                                            [{handler,default,logger_std_h,
1080                                              #{config=>#{type=>{file,F}}}}]]),
1081    ok = rpc:call(Node,logger,internal_init_logger,[]),
1082    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1083    #{primary:=#{filter_default:=log,filters:=[]},
1084      handlers:=[#{id:=default,filters:=DF,
1085                   config:=#{type:=file,file:=F,modes:=Modes}}],
1086      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1087
1088    %% Same, but with type={file,File,Modes}
1089    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1090    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1091    M = [raw,write],
1092    ok = rpc:call(Node,application,set_env,[kernel,logger,
1093                                            [{handler,default,logger_std_h,
1094                                              #{config=>#{type=>{file,F,M}}}}]]),
1095    ok = rpc:call(Node,logger,internal_init_logger,[]),
1096    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1097    #{primary:=#{filter_default:=log,filters:=[]},
1098      handlers:=[#{id:=default,filters:=DF,
1099                   config:=#{type:=file,file:=F,modes:=[delayed_write|M]}}],
1100      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1101
1102    %% Same, but with disk_log handler
1103    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1104    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1105    ok = rpc:call(Node,application,set_env,[kernel,logger,
1106                                            [{handler,default,logger_disk_log_h,
1107                                              #{config=>#{file=>F}}}]]),
1108    ok = rpc:call(Node,logger,internal_init_logger,[]),
1109    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1110    #{primary:=#{filter_default:=log,filters:=[]},
1111      handlers:=[#{id:=default,filters:=DF,config:=#{file:=F}}],
1112      module_levels:=[]} = rpc:call(Node,logger,get_config,[]),
1113
1114    %% Set primary filters and module level. No default handler.
1115    ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again
1116    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1117    ok = rpc:call(Node,application,set_env,
1118                  [kernel,logger,[{handler,default,undefined},
1119                                  {filters,stop,[{f1,{fun(_,_) -> log end,ok}}]},
1120                                  {module_level,debug,[?MODULE]}]]),
1121    ok = rpc:call(Node,logger,internal_init_logger,[]),
1122    ok = rpc:call(Node,logger,add_handlers,[kernel]),
1123    #{primary:=#{filter_default:=stop,filters:=[_]},
1124      handlers:=[],
1125      module_levels:=[{?MODULE,debug}]} = rpc:call(Node,logger,get_config,[]),
1126
1127    %% Bad config
1128    ok = rpc:call(Node,application,unset_env,[kernel,logger]),
1129
1130    ok = rpc:call(Node,application,set_env,[kernel,error_logger,bad]),
1131    {error,{bad_config,{kernel,{error_logger,bad}}}} =
1132        rpc:call(Node,logger,internal_init_logger,[]),
1133
1134    ok = rpc:call(Node,application,unset_env,[kernel,error_logger]),
1135    ok = rpc:call(Node,application,set_env,[kernel,logger_level,bad]),
1136    {error,{bad_config,{kernel,{logger_level,bad}}}} =
1137        rpc:call(Node,logger,internal_init_logger,[]),
1138
1139    ok = rpc:call(Node,application,unset_env,[kernel,logger_level]),
1140    ok = rpc:call(Node,application,set_env,
1141                  [kernel,logger,[{filters,stop,[bad]}]]),
1142    {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} =
1143        rpc:call(Node,logger,internal_init_logger,[]),
1144
1145    ok = rpc:call(Node,application,set_env,
1146                  [kernel,logger,[{filters,stop,[bad]}]]),
1147    {error,{bad_config,{kernel,{invalid_filters,[bad]}}}} =
1148        rpc:call(Node,logger,internal_init_logger,[]),
1149
1150    ok = rpc:call(Node,application,set_env,
1151                  [kernel,logger,[{filters,stop,[{f1,bad}]}]]),
1152    {error,{bad_config,{kernel,{invalid_filter,{f1,bad}}}}} =
1153        rpc:call(Node,logger,internal_init_logger,[]),
1154
1155    ok = rpc:call(Node,application,set_env,
1156                  [kernel,logger,MF=[{filters,stop,[]},{filters,log,[]}]]),
1157    {error,{bad_config,{kernel,{multiple_filters,MF}}}} =
1158        rpc:call(Node,logger,internal_init_logger,[]),
1159
1160    ok = rpc:call(Node,application,set_env,
1161                  [kernel,logger,[{module_level,bad,[?MODULE]}]]),
1162    {error,{bad_config,{kernel,{invalid_level,bad}}}} =
1163        rpc:call(Node,logger,internal_init_logger,[]),
1164
1165    ok.
1166
1167pretty_print(_Config) ->
1168    ok = logger:add_handler(?FUNCTION_NAME,logger_std_h,#{}),
1169    ok = logger:set_module_level([module1,module2],debug),
1170
1171    ct:capture_start(),
1172    logger:i(),
1173    ct:capture_stop(),
1174    I0 = ct:capture_get(),
1175
1176    ct:capture_start(),
1177    logger:i(primary),
1178    ct:capture_stop(),
1179    IPrim = ct:capture_get(),
1180
1181    ct:capture_start(),
1182    logger:i(handlers),
1183    ct:capture_stop(),
1184    IHs = ct:capture_get(),
1185
1186    ct:capture_start(),
1187    logger:i(proxy),
1188    ct:capture_stop(),
1189    IProxy = ct:capture_get(),
1190
1191    ct:capture_start(),
1192    logger:i(modules),
1193    ct:capture_stop(),
1194    IMs = ct:capture_get(),
1195
1196    I02 = lists:append([IPrim,IHs,IProxy,IMs]),
1197    %% ct:log("~p~n",[I0]),
1198    %% ct:log("~p~n",[I02]),
1199    I0 = I02,
1200
1201    ct:capture_start(),
1202    logger:i(handlers),
1203    ct:capture_stop(),
1204    IHs = ct:capture_get(),
1205
1206    Ids = logger:get_handler_ids(),
1207    IHs2 =
1208        lists:append(
1209          [begin
1210               ct:capture_start(),
1211               logger:i(Id),
1212               ct:capture_stop(),
1213               [_|IH] = ct:capture_get(),
1214               IH
1215           end || Id <- Ids]),
1216
1217    %% ct:log("~p~n",[IHs]),
1218    %% ct:log("~p~n",[["Handler configuration: \n"|IHs2]]),
1219    IHs = ["Handler configuration: \n"|IHs2],
1220    ok.
1221
1222%%%-----------------------------------------------------------------
1223%%% Internal
1224check_logged(Level,Format,Args,Meta) ->
1225    do_check_logged(Level,{Format,Args},Meta).
1226
1227check_logged(Level,Msg,Meta) when ?IS_REPORT(Msg) ->
1228    do_check_logged(Level,{report,Msg},Meta);
1229check_logged(Level,Msg,Meta) when ?IS_STRING(Msg) ->
1230    do_check_logged(Level,{string,Msg},Meta).
1231
1232do_check_logged(Level,Msg0,Meta0) ->
1233    receive
1234        {#{level:=Level,msg:=Msg,meta:=Meta},_} ->
1235            check_msg(Msg0,Msg),
1236            check_maps(Meta0,Meta,meta)
1237    after 500 ->
1238            ct:fail({timeout,no_log,process_info(self(),messages)})
1239    end.
1240
1241check_no_log() ->
1242    receive
1243        X -> ct:fail({got_unexpected_log,X})
1244    after 500 ->
1245            ok
1246    end.
1247
1248check_msg(Msg,Msg) ->
1249    ok;
1250check_msg({report,Expected},{report,Got}) when is_map(Expected), is_map(Got) ->
1251    check_maps(Expected,Got,msg);
1252check_msg(Expected,Got) ->
1253    ct:fail({unexpected,msg,Expected,Got}).
1254
1255check_maps(Expected,Got,What) ->
1256    case maps:merge(Got,Expected) of
1257        Got ->
1258            ok;
1259        _ ->
1260            ct:fail({unexpected,What,Expected,Got})
1261    end.
1262
1263%% Handler
1264adding_handler(#{add_call:=Fun}) ->
1265    Fun();
1266adding_handler(Config) ->
1267    maybe_send(add),
1268    {ok,Config}.
1269
1270removing_handler(#{rem_call:=Fun}) ->
1271    Fun();
1272removing_handler(_Config) ->
1273    maybe_send(remove),
1274    ok.
1275changing_config(_Old,#{conf_call:=Fun}) ->
1276    Fun();
1277changing_config(_Old,Config) ->
1278    maybe_send(changing_config),
1279    {ok,Config}.
1280
1281maybe_send(Msg) ->
1282    case whereis(callback_receiver) of
1283        undefined -> ok;
1284        Pid -> Pid ! Msg
1285    end.
1286
1287log(_Log,#{log_call:=Fun}) ->
1288    Fun();
1289log(Log,Config) ->
1290    TcProc  = maps:get(tc_proc,Config,self()),
1291    TcProc ! {Log,Config},
1292    ok.
1293
1294test_api(Level) ->
1295    logger:Level(#{Level=>rep}),
1296    ok = check_logged(Level,#{Level=>rep},#{}),
1297    logger:Level(#{Level=>rep},#{my=>meta}),
1298    ok = check_logged(Level,#{Level=>rep},#{my=>meta}),
1299    logger:Level("~w: ~w",[Level,fa]),
1300    ok = check_logged(Level,"~w: ~w",[Level,fa],#{}),
1301    logger:Level('~w: ~w',[Level,fa]),
1302    ok = check_logged(Level,'~w: ~w',[Level,fa],#{}),
1303    logger:Level(<<"~w: ~w">>,[Level,fa]),
1304    ok = check_logged(Level,<<"~w: ~w">>,[Level,fa],#{}),
1305    logger:Level("~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1306    ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1307    logger:Level(fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end,x,
1308                 #{my=>meta}),
1309    ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],#{my=>meta}),
1310    logger:Level(fun(x) -> {<<"~w: ~w ~w">>,[Level,fun_to_fa,meta]} end,x,
1311                 #{my=>meta}),
1312    ok = check_logged(Level,<<"~w: ~w ~w">>,[Level,fun_to_fa,meta],#{my=>meta}),
1313    logger:Level(fun(x) -> {'~w: ~w ~w',[Level,fun_to_fa,meta]} end,x,
1314                 #{my=>meta}),
1315    ok = check_logged(Level,'~w: ~w ~w',[Level,fun_to_fa,meta],#{my=>meta}),
1316    logger:Level(fun(x) -> #{Level=>fun_to_r,meta=>true} end,x,
1317                     #{my=>meta}),
1318    ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},#{my=>meta}),
1319    logger:Level(fun(x) -> <<"fun_to_s">> end,x,#{}),
1320    ok = check_logged(Level,<<"fun_to_s">>,#{}),
1321    logger:Level(F1=fun(x) -> {fun_to_bad} end,x,#{}),
1322    ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp",
1323                      [{F1,x},{fun_to_bad}],#{}),
1324    logger:Level(F2=fun(x) -> erlang:error(fun_that_crashes) end,x,#{}),
1325    ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp",
1326                      [{F2,x},{error,fun_that_crashes}],#{}),
1327    ok.
1328
1329test_log_function(Level) ->
1330    logger:log(Level,#{Level=>rep}),
1331    ok = check_logged(Level,#{Level=>rep},#{}),
1332    logger:log(Level,#{Level=>rep},#{my=>meta}),
1333    ok = check_logged(Level,#{Level=>rep},#{my=>meta}),
1334    logger:log(Level,"~w: ~w",[Level,fa]),
1335    ok = check_logged(Level,"~w: ~w",[Level,fa],#{}),
1336    logger:log(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1337    ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1338    logger:log(Level,fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end,
1339               x, #{my=>meta}),
1340    ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],#{my=>meta}),
1341    logger:log(Level,fun(x) -> {<<"~w: ~w ~w">>,[Level,fun_to_fa,meta]} end,
1342               x, #{my=>meta}),
1343    ok = check_logged(Level,<<"~w: ~w ~w">>,[Level,fun_to_fa,meta],#{my=>meta}),
1344    logger:log(Level,fun(x) -> {'~w: ~w ~w',[Level,fun_to_fa,meta]} end,
1345               x, #{my=>meta}),
1346    ok = check_logged(Level,'~w: ~w ~w',[Level,fun_to_fa,meta],#{my=>meta}),
1347    logger:log(Level,fun(x) -> #{Level=>fun_to_r,meta=>true} end,
1348               x, #{my=>meta}),
1349    ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},#{my=>meta}),
1350    logger:log(Level,fun(x) -> <<"fun_to_s">> end,x,#{}),
1351    ok = check_logged(Level,<<"fun_to_s">>,#{}),
1352    logger:log(Level,F1=fun(x) -> {fun_to_bad} end,x,#{}),
1353    ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp",
1354                      [{F1,x},{fun_to_bad}],#{}),
1355    logger:log(Level,F2=fun(x) -> erlang:error(fun_that_crashes) end,x,#{}),
1356    ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp",
1357                      [{F2,x},{error,fun_that_crashes}],#{}),
1358    logger:log(Level,fun(x) -> {{"~w: ~w ~w",[Level,fun_to_fa,meta]}, #{my=>override}} end,
1359               x, #{my=>meta}),
1360    ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],#{my=>override}),
1361    logger:log(Level,fun(x) -> {#{Level=>fun_to_r,meta=>true}, #{my=>override}} end,
1362               x, #{my=>meta}),
1363    ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},#{my=>override}),
1364    logger:log(Level,fun(x) -> {<<"fun_to_s">>,#{my=>override}} end,x,#{my=>meta}),
1365    ok = check_logged(Level,<<"fun_to_s">>,#{my=>override}),
1366    logger:log(Level, fun(x) -> ignore end, x, #{}),
1367    ok = check_no_log(),
1368    ok.
1369
1370test_macros(emergency=Level) ->
1371    ?LOG_EMERGENCY(#{Level=>rep}),
1372    ok = check_logged(Level,#{Level=>rep},?MY_LOC(1)),
1373    ?LOG_EMERGENCY(#{Level=>rep},#{my=>meta}),
1374    ok = check_logged(Level,#{Level=>rep},(?MY_LOC(1))#{my=>meta}),
1375    ?LOG_EMERGENCY("~w: ~w",[Level,fa]),
1376    ok = check_logged(Level,"~w: ~w",[Level,fa],?MY_LOC(1)),
1377    ?LOG_EMERGENCY("~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1378    ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],(?MY_LOC(1))#{my=>meta}),
1379    ?LOG_EMERGENCY(fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end,
1380                   x, #{my=>meta}),
1381    ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],
1382                      (?MY_LOC(3))#{my=>meta}),
1383    ?LOG_EMERGENCY(fun(x) -> #{Level=>fun_to_r,meta=>true} end, x, #{my=>meta}),
1384    ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},
1385                      (?MY_LOC(2))#{my=>meta}),
1386    ?LOG_EMERGENCY(fun(x) -> <<"fun_to_s">> end,x,#{}),
1387    ok = check_logged(Level,<<"fun_to_s">>,?MY_LOC(1)),
1388    F1=fun(x) -> {fun_to_bad} end,
1389    ?LOG_EMERGENCY(F1,x,#{}),
1390    ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp",
1391                      [{F1,x},{fun_to_bad}],#{}),
1392    F2=fun(x) -> erlang:error(fun_that_crashes) end,
1393    ?LOG_EMERGENCY(F2,x,#{}),
1394    ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp",
1395                      [{F2,x},{error,fun_that_crashes}],#{}),
1396    ok.
1397
1398test_log_macro(Level) ->
1399    ?LOG(Level,#{Level=>rep}),
1400    ok = check_logged(Level,#{Level=>rep},?MY_LOC(1)),
1401    ?LOG(Level,#{Level=>rep},#{my=>meta}),
1402    ok = check_logged(Level,#{Level=>rep},(?MY_LOC(1))#{my=>meta}),
1403    ?LOG(Level,"~w: ~w",[Level,fa]),
1404    ok = check_logged(Level,"~w: ~w",[Level,fa],?MY_LOC(1)),
1405    ?LOG(Level,"~w: ~w ~w",[Level,fa,meta],#{my=>meta}),
1406    ok = check_logged(Level,"~w: ~w ~w",[Level,fa,meta],(?MY_LOC(1))#{my=>meta}),
1407    ?LOG(Level,fun(x) -> {"~w: ~w ~w",[Level,fun_to_fa,meta]} end,
1408                   x, #{my=>meta}),
1409    ok = check_logged(Level,"~w: ~w ~w",[Level,fun_to_fa,meta],
1410                      (?MY_LOC(3))#{my=>meta}),
1411    ?LOG(Level,fun(x) -> #{Level=>fun_to_r,meta=>true} end, x, #{my=>meta}),
1412    ok = check_logged(Level,#{Level=>fun_to_r,meta=>true},
1413                      (?MY_LOC(2))#{my=>meta}),
1414    ?LOG(Level,fun(x) -> <<"fun_to_s">> end,x,#{}),
1415    ok = check_logged(Level,<<"fun_to_s">>,?MY_LOC(1)),
1416    F1=fun(x) -> {fun_to_bad} end,
1417    ?LOG(Level,F1,x,#{}),
1418    ok = check_logged(Level,"LAZY_FUN ERROR: ~tp; Returned: ~tp",
1419                      [{F1,x},{fun_to_bad}],#{}),
1420    F2=fun(x) -> erlang:error(fun_that_crashes) end,
1421    ?LOG(Level,F2,x,#{}),
1422    ok = check_logged(Level,"LAZY_FUN CRASH: ~tp; Reason: ~tp",
1423                      [{F2,x},{error,fun_that_crashes}],#{}),
1424    ok.
1425
1426%%%-----------------------------------------------------------------
1427%%% Called by macro ?TRY(X)
1428my_try(Fun) ->
1429    try Fun() catch C:R -> {C,R} end.
1430
1431check_config(crash) ->
1432    erlang:error({badmatch,3});
1433check_config(_) ->
1434    ok.
1435
1436%% this function is also a test. When logger.hrl used non-qualified
1437%%  apply/3 call, any module that was implementing apply/3 could
1438%%  not use any logging macro
1439apply(_Any, _Any, _Any) ->
1440    ok.
1441