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_formatter_SUITE).
21
22-compile(export_all).
23
24-include_lib("common_test/include/ct.hrl").
25-include_lib("kernel/include/logger.hrl").
26
27-define(TRY(X), my_try(fun() -> X end)).
28
29suite() ->
30    [{timetrap,{seconds,30}}].
31
32init_per_suite(Config) ->
33    Config.
34
35end_per_suite(_Config) ->
36    ok.
37
38init_per_group(_Group, Config) ->
39    Config.
40
41end_per_group(_Group, _Config) ->
42    ok.
43
44init_per_testcase(_TestCase, Config) ->
45    Config.
46
47end_per_testcase(Case, Config) ->
48    try apply(?MODULE,Case,[cleanup,Config])
49    catch error:undef -> ok
50    end,
51    ok.
52
53groups() ->
54    [].
55
56all() ->
57    [default,
58     legacy_header,
59     error_logger_notice_header,
60     single_line,
61     template,
62     format_msg,
63     report_cb,
64     max_size,
65     depth,
66     chars_limit,
67     format_mfa,
68     format_time,
69     level_or_msg_in_meta,
70     faulty_log,
71     faulty_config,
72     faulty_msg,
73     check_config,
74     update_config].
75
76default(_Config) ->
77    String1 = format(info,{"~p",[term]},#{},#{}),
78    ct:log(String1),
79    [_DateTime,"info:","term\n"] = string:lexemes(String1," "),
80
81    Time = timestamp(),
82    ExpectedTimestamp = default_time_format(Time),
83    String2 = format(info,{"~p",[term]},#{time=>Time},#{}),
84    ct:log(String2),
85    " info: term\n" = string:prefix(String2,ExpectedTimestamp),
86    ok.
87
88legacy_header(_Config) ->
89    Time = timestamp(),
90    String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true,
91                                                        single_line=>false}),
92    ct:log(String1),
93    "=INFO REPORT==== "++Rest = String1,
94    [Timestamp,"\nterm\n"] = string:lexemes(Rest," ="),
95    [D,M,Y,H,Min,S,Micro] = string:lexemes(Timestamp,"-:."),
96    integer(D,31),
97    integer(Y,2018,infinity),
98    integer(H,23),
99    integer(Min,59),
100    integer(S,59),
101    integer(Micro,999999),
102    true = lists:member(M,["Jan","Feb","Mar","Apr","May","Jun",
103                           "Jul","Aug","Sep","Oct","Nov","Dec"]),
104
105    String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false,
106                                                        single_line=>false}),
107    ct:log(String2),
108    ExpectedTimestamp = default_time_format(Time),
109    " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp),
110
111    String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad,
112                                                        single_line=>false}),
113    ct:log(String3),
114    String3 = String2,
115
116    String4 = format(info,{"~p",[term]},#{time=>Time},
117                     #{legacy_header=>true,
118                       single_line=>true}), % <---ignored
119    ct:log(String4),
120    String4 = String1,
121
122    String5 = format(info,{"~p",[term]},#{}, % <--- no time
123                     #{legacy_header=>true,
124                       single_line=>false}),
125    ct:log(String5),
126    "=INFO REPORT==== "++_ = String5,
127    ok.
128
129error_logger_notice_header(_Config) ->
130    Meta1 = #{error_logger=>#{tag => info_report,type => std_info}},
131    String1 = format(notice,{"~p",[term]},Meta1,
132                     #{legacy_header=>true,
133                       error_logger_notice_header=>notice}),
134    ct:log(String1),
135    "=NOTICE REPORT==== "++_ = String1,
136
137    String2 = format(notice,{"~p",[term]},Meta1,
138                     #{legacy_header=>true,
139                       error_logger_notice_header=>info}),
140    ct:log(String2),
141    "=INFO REPORT==== "++_ = String2,
142
143    String3 = format(notice,{"~p",[term]},#{},
144                     #{legacy_header=>true,
145                       error_logger_notice_header=>notice}),
146    ct:log(String3),
147    "=NOTICE REPORT==== "++_ = String3,
148
149    String4 = format(notice,{"~p",[term]},#{},
150                     #{legacy_header=>true,
151                       error_logger_notice_header=>info}),
152    ct:log(String4),
153    "=NOTICE REPORT==== "++_ = String4,
154
155    ok.
156
157single_line(_Config) ->
158    Time = timestamp(),
159    ExpectedTimestamp = default_time_format(Time),
160    String1 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>true}),
161    ct:log(String1),
162    " info: term\n" = string:prefix(String1,ExpectedTimestamp),
163
164    String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>false}),
165    ct:log(String2),
166    " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp),
167
168    String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>bad}),
169
170
171    %% Test that no extra commas/spaces are added when removing
172    %% newlines, especially not after "=>" in a map association (as
173    %% was the case in OTP-21.0, when the only single_line adjustment
174    %% was done by regexp replacement of "\n" by ", ").
175    Prefix =
176        "Some characters to fill the line ------------------------------------- ",
177    String3 = format(info,{"~s~p~n~s~p~n",[Prefix,
178                                           lists:seq(1,10),
179                                           Prefix,
180                                           #{a=>map,with=>a,few=>accociations}]},
181                     #{time=>Time},
182                     #{single_line=>true}),
183    ct:log(String3),
184    match = re:run(String3,"\\[1,2,3,4,5,6,7,8,9,10\\]",[{capture,none}]),
185    match = re:run(String3,
186                   "#{a => map,few => accociations,with => a}",
187                   [{capture,none}]),
188
189    %% This part is added to make sure that the previous test made
190    %% sense, i.e. that there would actually be newlines inside the
191    %% list and map.
192    String4 = format(info,{"~s~p~n~s~p~n",[Prefix,
193                                           lists:seq(1,10),
194                                           Prefix,
195                                           #{a=>map,with=>a,few=>accociations}]},
196                     #{time=>Time},
197                     #{single_line=>false}),
198    ct:log(String4),
199    match = re:run(String4,"\\[1,2,3,\n",[global,{capture,none}]),
200    {match,Match4} = re:run(String4,"=>\n",[global,{capture,all}]),
201    3 = length(Match4),
202
203    %% Test that big metadata fields do not get line breaks
204    String5 = format(info,"",
205                     #{mymeta=>lists:seq(1,100)},
206                     #{single_line=>true,template=>[mymeta,"\n"]}),
207    ct:log(String5),
208    [_] = string:lexemes(String5,"\n"),
209
210    %% Ensure that the previous test made sense, i.e. that the
211    %% metadata field does produce multiple lines if
212    %% single_line==false.
213    String6 = format(info,"",
214                     #{mymeta=>lists:seq(1,100)},
215                     #{single_line=>false,template=>[mymeta,"\n"]}),
216    ct:log(String6),
217    [_,_|_] = string:lexemes(String6,"\n"),
218
219    ok.
220
221template(_Config) ->
222    Time = timestamp(),
223
224    Template1 = [msg],
225    String1 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template1}),
226    ct:log(String1),
227    "term" = String1,
228
229    Template2 = [msg,unknown],
230    String2 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template2}),
231    ct:log(String2),
232    "term" = String2,
233
234    Template3 = ["string"],
235    String3 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template3}),
236    ct:log(String3),
237    "string" = String3,
238
239    Template4 = ["string\nnewline"],
240    String4 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template4,
241                                                        single_line=>true}),
242    ct:log(String4),
243    "string\nnewline" = String4,
244
245    Template5 = [],
246    String5 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template5}),
247    ct:log(String5),
248    "" = String5,
249
250    Template6 = [<<"binary">>],
251    String6 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template6}),
252    ct:log(String6),
253    "binary" = String6,
254
255    Template7 = [{metakey,[[$e,<<"x">>,$i,[<<"s">>],":"],metakey],[[[[[[[[["does ",<<"not">>," exist"]]]]]]]]]},[[[<<" more ">>]],"deep"]],
256    String7 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template7}),
257    ct:log(String7),
258    "does not exist more deep" = String7,
259
260    Ref8 = erlang:make_ref(),
261    Meta8 = #{atom=>some_atom,
262              integer=>632,
263              list=>[list,"string",4321,#{},{tuple}],
264              mfa=>{mod,func,0},
265              pid=>self(),
266              ref=>Ref8,
267              string=>"some string",
268              time=>Time,
269              tuple=>{1,atom,"list"},
270              nested=>#{subkey=>subvalue}},
271    Template8 = lists:join(";",lists:sort(maps:keys(maps:remove(nested,Meta8))) ++
272                               [[nested,subkey]]),
273    String8 = format(info,{"~p",[term]},Meta8,#{template=>Template8,
274                                                single_line=>true}),
275    ct:log(String6),
276    SelfStr = pid_to_list(self()),
277    RefStr8 = ref_to_list(Ref8),
278    ListStr = "[list,\"string\",4321,#{},{tuple}]",
279    ExpectedTime8 = default_time_format(Time),
280    ["some_atom",
281     "632",
282     ListStr,
283     "mod:func/0",
284     SelfStr,
285     RefStr8,
286     "some string",
287     ExpectedTime8,
288     "{1,atom,\"list\"}",
289     "subvalue"] = string:lexemes(String8,";"),
290
291    Meta9 = #{time=>Time,
292              nested=>#{key1=>#{subkey1=>value1},
293                        key2=>value2}},
294    Template9 = lists:join(";",[nested,
295                                [nested,key1],
296                                [nested,key1,subkey1],
297                                [nested,key2],
298                                [nested,key2,subkey2],
299                                [nested,key3],
300                                [nested,key3,subkey3]]),
301    String9 = format(info,{"~p",[term]},Meta9,#{template=>Template9,
302                                                single_line=>true}),
303    ct:log(String9),
304    [MultipleKeysStr9,
305     "#{subkey1 => value1}",
306     "value1",
307     "value2",
308     "",
309     "",
310     ""] = string:split(String9,";",all),
311    %% Order of keys is not fixed
312    case MultipleKeysStr9 of
313        "#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok;
314        "#{key1 => #{subkey1 => value1},key2 => value2}" -> ok;
315        _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr9})
316    end,
317
318    Meta10 = #{time=>Time,
319              nested=>#{key1=>#{subkey1=>value1},
320                        key2=>value2}},
321    Template10 =
322        lists:join(
323          ";",
324          [{nested,["exist:",nested],["noexist"]},
325           {[nested,key1],["exist:",[nested,key1]],["noexist"]},
326           {[nested,key1,subkey1],["exist:",[nested,key1,subkey1]],["noexist"]},
327           {[nested,key2],["exist:",[nested,key2]],["noexist"]},
328           {[nested,key2,subkey2],["exist:",[nested,key2,subkey2]],["noexist"]},
329           {[nested,key3],["exist:",[nested,key3]],["noexist"]},
330           {[nested,key3,subkey3],["exist:",[nested,key3,subkey3]],["noexist"]}]),
331    String10 = format(info,{"~p",[term]},Meta10,#{template=>Template10,
332                                                 single_line=>true}),
333    ct:log(String10),
334    [MultipleKeysStr10,
335     "exist:#{subkey1 => value1}",
336     "exist:value1",
337     "exist:value2",
338     "noexist",
339     "noexist",
340     "noexist"] = string:split(String10,";",all),
341    %% Order of keys is not fixed
342    case MultipleKeysStr10 of
343        "exist:#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok;
344        "exist:#{key1 => #{subkey1 => value1},key2 => value2}" -> ok;
345        _ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr10})
346    end,
347
348    ok.
349
350format_msg(_Config) ->
351    Template = [msg],
352
353    String1 = format(info,{"~p",[term]},#{},#{template=>Template}),
354    ct:log(String1),
355    "term" = String1,
356
357    String2 = format(info,{"list",[term]},#{},#{template=>Template}),
358    ct:log(String2),
359    "FORMAT ERROR: \"list\" - [term]" = String2,
360
361    String3 = format(info,{report,term},#{},#{template=>Template}),
362    ct:log(String3),
363    "term" = String3,
364
365    String4 = format(info,{report,term},
366                     #{report_cb=>fun(_)-> {"formatted",[]} end},
367                     #{template=>Template}),
368    ct:log(String4),
369    "formatted" = String4,
370
371    String5 = format(info,{report,term},
372                     #{report_cb=>fun(_)-> faulty_return end},
373                     #{template=>Template}),
374    ct:log(String5),
375    "REPORT_CB/1 ERROR: term; Returned: faulty_return" = String5,
376
377    String6 = format(info,{report,term},
378                     #{report_cb=>fun(_)-> erlang:error(fun_crashed) end},
379                     #{template=>Template}),
380    ct:log(String6),
381    "REPORT_CB/1 CRASH: term; Reason: {error,fun_crashed,"++_ = String6,
382
383    String7 = format(info,{report,term},
384                     #{report_cb=>fun(_,_)-> ['not',a,string] end},
385                     #{template=>Template}),
386    ct:log(String7),
387    "REPORT_CB/2 ERROR: term; Returned: ['not',a,string]" = String7,
388
389    String8 = format(info,{report,term},
390                     #{report_cb=>fun(_,_)-> faulty_return end},
391                     #{template=>Template}),
392    ct:log(String8),
393    "REPORT_CB/2 ERROR: term; Returned: faulty_return" = String8,
394
395    String9 = format(info,{report,term},
396                     #{report_cb=>fun(_,_)-> erlang:error(fun_crashed) end},
397                     #{template=>Template}),
398    ct:log(String9),
399    "REPORT_CB/2 CRASH: term; Reason: {error,fun_crashed,"++_ = String9,
400
401    %% strings are not formatted
402    String10 = format(info,{string,"string"},
403                     #{report_cb=>fun(_)-> {"formatted",[]} end},
404                     #{template=>Template}),
405    ct:log(String10),
406    "string" = String10,
407
408    String11 = format(info,{string,['not',printable,list]},
409                     #{report_cb=>fun(_)-> {"formatted",[]} end},
410                     #{template=>Template}),
411    ct:log("~ts",[String11]), % avoiding ct_log crash
412    "FORMAT ERROR: \"~ts\" - [['not',printable,list]]" = String11,
413
414    String12 = format(info,{string,"string"},#{},#{template=>Template}),
415    ct:log(String12),
416    "string" = String12,
417
418    ok.
419
420report_cb(_Config) ->
421    Template = [msg],
422    MetaFun = fun(_) -> {"meta_rcb",[]} end,
423    ConfigFun = fun(_) -> {"config_rcb",[]} end,
424    "term" = format(info,{report,term},#{},#{template=>Template}),
425    "meta_rcb" =
426        format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template}),
427    "config_rcb" =
428        format(info,{report,term},#{},#{template=>Template,
429                                        report_cb=>ConfigFun}),
430    "config_rcb" =
431        format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template,
432                                                          report_cb=>ConfigFun}),
433    ok.
434
435max_size(_Config) ->
436    Cfg = #{template=>[msg],
437            single_line=>false},
438    "12345678901234567890" =
439        format(info,{"12345678901234567890",[]},#{},Cfg),
440    %% application:set_env(kernel,logger_max_size,11),
441    %% "12345678901234567890" = % min value is 50, so this is not limited
442    %%     format(info,{"12345678901234567890",[]},#{},Cfg),
443    %% "12345678901234567890123456789012345678901234567..." = % 50
444    %%     format(info,
445    %%            {"123456789012345678901234567890123456789012345678901234567890",
446    %%             []},
447    %%            #{},
448    %%            Cfg),
449    %% application:set_env(kernel,logger_max_size,53),
450    %% "12345678901234567890123456789012345678901234567890..." = %53
451    %%     format(info,
452    %%            {"123456789012345678901234567890123456789012345678901234567890",
453    %%             []},
454    %%            #{},
455    %%            Cfg),
456    "123456789012..." =
457        format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}),
458    "12345678901234567890" =
459        format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>unlimited}),
460    %% Check that one newline at the end of the line is kept (if it exists)
461    "12345678901...\n" =
462        format(info,{"12345678901234567890\n",[]},#{},Cfg#{max_size=>15}),
463    "12345678901...\n" =
464        format(info,{"12345678901234567890",[]},#{},Cfg#{template=>[msg,"\n"],
465                                                         max_size=>15}),
466    ok.
467max_size(cleanup,_Config) ->
468    application:unset_env(kernel,logger_max_size),
469    ok.
470
471depth(_Config) ->
472    Template = [msg],
473    "[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" =
474        format(info,
475               {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
476               #{},
477               #{template=>Template}),
478    application:set_env(kernel,error_logger_format_depth,11),
479    "[1,2,3,4,5,6,7,8,9,0|...]" =
480        format(info,
481               {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
482               #{},
483               #{template=>Template}),
484    "[1,2,3,4,5,6,7,8,9,0,1,2|...]" =
485        format(info,
486               {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
487               #{},
488               #{template=>Template,
489                 depth=>13}),
490    "[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" =
491        format(info,
492               {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
493               #{},
494               #{template=>Template,
495                 depth=>unlimited}),
496    ok.
497depth(cleanup,_Config) ->
498    application:unset_env(kernel,error_logger_format_depth),
499    ok.
500
501chars_limit(_Config) ->
502    FA = {"LoL: ~p~nL: ~p~nMap: ~p~n",
503                [lists:duplicate(10,lists:seq(1,100)),
504                 lists:seq(1,100),
505                 maps:from_list(lists:zip(lists:seq(1,100),
506                                          lists:duplicate(100,value)))]},
507    Meta = #{time=>timestamp()},
508    Template = [time," - ", msg, "\n"],
509    FC = #{template=>Template,
510           depth=>unlimited,
511           max_size=>unlimited,
512           chars_limit=>unlimited,
513           single_line=>true},
514    CL1 = 80,
515    String1 = format(info,FA,Meta,FC#{chars_limit=>CL1}),
516    L1 = string:length(String1),
517    ct:log("String1: ~p~nLength1: ~p~n",[lists:flatten(String1),L1]),
518    true = L1 > CL1,
519    true = L1 < CL1 + 15,
520
521    String2 = format(info,FA,Meta,FC#{chars_limit=>CL1,depth=>10}),
522    L2 = string:length(String2),
523    ct:log("String2: ~p~nLength2: ~p~n",[lists:flatten(String2),L2]),
524    String2 = String1,
525
526    CL3 = 200,
527    String3 = format(info,FA,Meta,FC#{chars_limit=>CL3}),
528    L3 = string:length(String3),
529    ct:log("String3: ~p~nLength3: ~p~n",[lists:flatten(String3),L3]),
530    true = L3 > CL3,
531    true = L3 < CL3 + 15,
532
533    String4 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10}),
534    L4 = string:length(String4),
535    ct:log("String4: ~p~nLength4: ~p~n",[lists:flatten(String4),L4]),
536    true = L4 > CL3,
537    true = L4 < CL3 + 15,
538
539    %% Test that max_size truncates the string which is limited by
540    %% depth and chars_limit
541    MS5 = 150,
542    String5 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10,max_size=>MS5}),
543    L5 = string:length(String5),
544    ct:log("String5: ~p~nLength5: ~p~n",[String5,L5]),
545    L5 = MS5,
546    true = lists:prefix(lists:sublist(String5,L5-4),String4),
547
548    %% Test that chars_limit limits string also
549    Str = "123456789012345678901234567890123456789012345678901234567890123456789",
550    CL6 = 80,
551    String6 = format(info,{string,Str},Meta,FC#{chars_limit=>CL6}),
552    L6 = string:length(String6),
553    ct:log("String6: ~p~nLength6: ~p~n",[String6,L6]),
554    L6 = CL6,
555
556    ok.
557
558format_mfa(_Config) ->
559    Template = [mfa],
560
561    Meta1 = #{mfa=>{mod,func,0}},
562    String1 = format(info,{"~p",[term]},Meta1,#{template=>Template}),
563    ct:log(String1),
564    "mod:func/0" = String1,
565
566    Meta2 = #{mfa=>{mod,func,[]}},
567    String2 = format(info,{"~p",[term]},Meta2,#{template=>Template}),
568    ct:log(String2),
569    "mod:func/0" = String2,
570
571    Meta3 = #{mfa=>"mod:func/0"},
572    String3 = format(info,{"~p",[term]},Meta3,#{template=>Template}),
573    ct:log(String3),
574    "mod:func/0" = String3,
575
576    Meta4 = #{mfa=>othermfa},
577    String4 = format(info,{"~p",[term]},Meta4,#{template=>Template}),
578    ct:log(String4),
579    "othermfa" = String4,
580
581    Meta5 = #{mfa=>{'m o d','a\x{281}b',['  ']}},
582    String5 = format(info,{"~p",[term]},Meta5,#{template=>Template}),
583    ct:log(String5),
584    "'m o d':'a\x{281}b'/1" = String5,
585
586    ok.
587
588format_time(_Config) ->
589    Time = timestamp(),
590    Meta = #{time=>Time},
591    FC = #{template=>[time]},
592    Msg = {string,""},
593    ExpectedLocal = default_time_format(Time,false),
594    ExpectedUtc = default_time_format(Time,true),
595
596    %% default - local time
597    ExpectedLocal = format(info,Msg,Meta,FC),
598
599    %% time_offset config parameter to formatter
600    ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}),
601    ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}),
602
603    %% stdlib utc_log works when time_offset parameter is not set
604    application:set_env(stdlib,utc_log,true),
605    ExpectedUtc = format(info,Msg,Meta,FC),
606
607    %% sasl utc_log overwrites stdlib utc_log
608    application:set_env(sasl,utc_log,false),
609    ExpectedLocal = format(info,Msg,Meta,FC),
610
611    %% sasl utc_log overwrites stdlib utc_log
612    application:set_env(sasl,utc_log,true),
613    application:set_env(stdlib,utc_log,false),
614    ExpectedUtc = format(info,Msg,Meta,FC),
615
616    %% time_offset config parameter to formatter
617    %% overwrites sasl and stdlib utc_log
618    application:set_env(sasl,utc_log,false),
619    ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}),
620
621    %% time_offset config parameter to formatter
622    %% overwrites sasl and stdlib utc_log
623    application:set_env(sasl,utc_log,true),
624    application:set_env(stdlib,utc_log,true),
625    ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}),
626
627    %% time_designator config parameter to formatter
628    ExpectedLocalS = default_time_format(Time,false,$\s),
629    ExpectedUtcS = default_time_format(Time,true,$\s),
630
631    ExpectedLocalS = format(info,Msg,Meta,FC#{time_offset=>"",
632                                              time_designator=>$\s}),
633    ExpectedUtcS = format(info,Msg,Meta,FC#{time_offset=>"Z",
634                                            time_designator=>$\s}),
635
636    ok.
637
638format_time(cleanup,_Config) ->
639    application:unset_env(sasl,utc_log),
640    application:unset_env(stdlib,utc_log),
641    ok.
642
643level_or_msg_in_meta(_Config) ->
644    %% The template contains atoms to pick out values from meta,
645    %% or level/msg to add these from the log event. What if you have
646    %% a key named 'level' or 'msg' in meta and want to display
647    %% its value?
648    %% For now we simply ignore Meta on this and display the
649    %% actual level and msg from the log event.
650
651    Meta = #{level=>mylevel,
652                 msg=>"metamsg"},
653    Template = [level,";",msg],
654    String = format(info,{"~p",[term]},Meta,#{template=>Template}),
655    ct:log(String),
656    "info;term" = String, % so mylevel and "metamsg" are ignored
657
658    ok.
659
660faulty_log(_Config) ->
661    %% Unexpected log (should be type logger:log_event()) - print error
662    {error,
663     function_clause,
664     {logger_formatter,format,[_,_],_}} =
665        ?TRY(logger_formatter:format(unexp_log,#{})),
666    ok.
667
668faulty_config(_Config) ->
669    {error,
670     function_clause,
671     {logger_formatter,format,[_,_],_}} =
672        ?TRY(logger_formatter:format(#{level=>info,
673                                       msg=>{"~p",[term]},
674                                       meta=>#{time=>timestamp()}},
675                                     unexp_config)),
676    ok.
677
678faulty_msg(_Config) ->
679    {error,
680     function_clause,
681     {logger_formatter,_,_,_}} =
682        ?TRY(logger_formatter:format(#{level=>info,
683                                       msg=>term,
684                                       meta=>#{time=>timestamp()}},
685                                     #{})),
686    ok.
687
688-define(cfgerr(X), {error,{invalid_formatter_config,logger_formatter,X}}).
689check_config(_Config) ->
690    ok = logger_formatter:check_config(#{}),
691    ?cfgerr(bad) = logger_formatter:check_config(bad),
692
693    C1 = #{chars_limit => 1,
694           depth => 1,
695           legacy_header => true,
696           error_logger_notice_header => info,
697           max_size => 1,
698           report_cb => fun(R) -> {"~p",[R]} end,
699           single_line => false,
700           template => [],
701           time_designator => $T,
702           time_offset => 0},
703    ok = logger_formatter:check_config(C1),
704
705    ok = logger_formatter:check_config(#{chars_limit => unlimited}),
706    ?cfgerr({chars_limit,bad}) =
707        logger_formatter:check_config(#{chars_limit => bad}),
708
709    ok = logger_formatter:check_config(#{depth => unlimited}),
710    ?cfgerr({depth,bad}) =
711        logger_formatter:check_config(#{depth => bad}),
712
713    ok = logger_formatter:check_config(#{legacy_header => false}),
714    ?cfgerr({legacy_header,bad}) =
715        logger_formatter:check_config(#{legacy_header => bad}),
716
717    ok = logger_formatter:check_config(#{error_logger_notice_header => notice}),
718    ?cfgerr({error_logger_notice_header,bad}) =
719        logger_formatter:check_config(#{error_logger_notice_header => bad}),
720
721    ok = logger_formatter:check_config(#{max_size => unlimited}),
722    ?cfgerr({max_size,bad}) =
723        logger_formatter:check_config(#{max_size => bad}),
724
725    ok =
726        logger_formatter:check_config(#{report_cb => fun(_,_) -> "" end}),
727    ?cfgerr({report_cb,F}) =
728        logger_formatter:check_config(#{report_cb => F=fun(_,_,_) -> {"",[]} end}),
729    ?cfgerr({report_cb,bad}) =
730        logger_formatter:check_config(#{report_cb => bad}),
731
732    ok = logger_formatter:check_config(#{single_line => true}),
733    ?cfgerr({single_line,bad}) =
734        logger_formatter:check_config(#{single_line => bad}),
735
736    Ts = [[key],
737          [[key1,key2]],
738          [{key,[key],[]}],
739          [{[key1,key2],[[key1,key2]],["noexist"]}],
740          ["string"]],
741    [begin
742         ct:log("check template: ~p",[T]),
743         ok = logger_formatter:check_config(#{template => T})
744     end
745     || T <- Ts],
746
747    ETs = [bad,
748           [{key,bad}],
749           [{key,[key],bad}],
750           [{key,[key],"bad"}],
751           "bad",
752           [[key,$a,$b,$c]],
753           [[$a,$b,$c,key]]],
754    [begin
755         ct:log("check template: ~p",[T]),
756         {error,{invalid_formatter_template,logger_formatter,T}} =
757         logger_formatter:check_config(#{template => T})
758     end
759     || T <- ETs],
760
761    ?cfgerr({time_designator,bad}) =
762        logger_formatter:check_config(#{time_designator => bad}),
763    ?cfgerr({time_designator,"b"}) =
764        logger_formatter:check_config(#{time_designator => "b"}),
765
766    ok = logger_formatter:check_config(#{time_offset => -1}),
767    ok = logger_formatter:check_config(#{time_offset => "+02:00"}),
768    ok = logger_formatter:check_config(#{time_offset => "-23:59"}),
769    ok = logger_formatter:check_config(#{time_offset => "+24:00"}),
770    ok = logger_formatter:check_config(#{time_offset => "-25:00"}),
771    ?cfgerr({time_offset,bad}) =
772        logger_formatter:check_config(#{time_offset => bad}),
773    ?cfgerr({time_offset,"02:00"}) =
774        logger_formatter:check_config(#{time_offset => "02:00"}),
775    ?cfgerr({time_offset,"+02"}) =
776        logger_formatter:check_config(#{time_offset => "+02"}),
777
778    ok.
779
780%% Test that formatter config can be changed, and that the default
781%% template is updated accordingly
782update_config(_Config) ->
783    {error,{not_found,?MODULE}} = logger:update_formatter_config(?MODULE,#{}),
784
785    logger:add_handler_filter(default,silence,{fun(_,_) -> stop end,ok}),
786    ok = logger:add_handler(?MODULE,?MODULE,#{}),
787    D = lists:seq(1,1000),
788    logger:notice("~p~n",[D]),
789    {Lines1,C1} = check_log(),
790    [ct:log(L) || L <- Lines1],
791    ct:log("~p",[C1]),
792    [Line1] = Lines1,
793    [_Time,"notice: "++D1] = string:split(Line1," "),
794    true = length(D1)>3000,
795    true = #{}==C1,
796
797    ok = logger:update_formatter_config(?MODULE,single_line,false),
798    logger:notice("~p~n",[D]),
799    {Lines2,C2} = check_log(),
800    [ct:log(L) || L <- Lines2],
801    ct:log("~p",[C2]),
802    true = length(Lines2)>50,
803    true = #{single_line=>false}==C2,
804
805    ok = logger:update_formatter_config(?MODULE,#{legacy_header=>true}),
806    logger:notice("~p~n",[D]),
807    {Lines3,C3} = check_log(),
808    [ct:log(L) || L <- Lines3],
809    ct:log("~p",[C3]),
810    ["=NOTICE REPORT==== "++_|D3] = Lines3,
811    true = length(D3)>50,
812    true = #{legacy_header=>true,single_line=>false}==C3,
813
814    ok = logger:update_formatter_config(?MODULE,single_line,true),
815    logger:notice("~p~n",[D]),
816    {Lines4,C4} = check_log(),
817    [ct:log(L) || L <- Lines4],
818    ct:log("~p",[C4]),
819    ["=NOTICE REPORT==== "++_,D4] = Lines4,
820    true = length(D4)>3000,
821    true = #{legacy_header=>true,single_line=>true}==C4,
822
823    %% Finally, check that error_logger_notice_header works, default=info
824    error_logger:info_msg("~p",[D]),
825    {Lines5,C5} = check_log(),
826    [ct:log(L) || L <- Lines5],
827    ct:log("~p",[C5]),
828    ["=INFO REPORT==== "++_,_D5] = Lines5,
829
830    ok=logger:update_formatter_config(?MODULE,error_logger_notice_header,notice),
831    error_logger:info_msg("~p",[D]),
832    {Lines6,C6} = check_log(),
833    [ct:log(L) || L <- Lines6],
834    ct:log("~p",[C6]),
835    ["=NOTICE REPORT==== "++_,_D6] = Lines6,
836
837    {error,{invalid_formatter_config,bad}} =
838        logger:update_formatter_config(?MODULE,bad),
839    {error,{invalid_formatter_config,logger_formatter,{depth,bad}}} =
840        logger:update_formatter_config(?MODULE,depth,bad),
841
842    ok.
843
844update_config(cleanup,_Config) ->
845    _ = logger:remove_handler(?MODULE),
846    _ = logger:remove_handler_filter(default,silence),
847    ok.
848
849%%%-----------------------------------------------------------------
850%%% Internal
851format(Level,Msg,Meta,Config) ->
852    format(#{level=>Level,msg=>Msg,meta=>add_time(Meta)},Config).
853
854format(Log,Config) ->
855    unicode:characters_to_list(logger_formatter:format(Log,Config)).
856
857default_time_format(Timestamp) ->
858    default_time_format(Timestamp,false).
859
860default_time_format(Timestamp,Utc) ->
861    default_time_format(Timestamp,Utc,$T).
862
863default_time_format(Timestamp,Utc,Sep) ->
864    Offset = if Utc -> "Z";
865                true -> ""
866             end,
867    calendar:system_time_to_rfc3339(Timestamp,[{unit,microsecond},
868                                               {time_designator,Sep},
869                                               {offset,Offset}]).
870
871integer(Str) ->
872    is_integer(list_to_integer(Str)).
873integer(Str,Max) ->
874    integer(Str,0,Max).
875integer(Str,Min,Max) ->
876    Int = list_to_integer(Str),
877    Int >= Min andalso Int =<Max.
878
879%%%-----------------------------------------------------------------
880%%% Called by macro ?TRY(X)
881my_try(Fun) ->
882    try Fun() catch C:R:S -> {C,R,hd(S)} end.
883
884timestamp() ->
885    logger:timestamp().
886
887%% necessary?
888add_time(#{time:=_}=Meta) ->
889    Meta;
890add_time(Meta) ->
891    Meta#{time=>timestamp()}.
892
893%%%-----------------------------------------------------------------
894%%% handler callback
895log(Log,#{formatter:={M,C}}) ->
896    put(log,{M:format(Log,C),C}),
897    ok.
898
899check_log() ->
900    {S,C} = erase(log),
901    {string:lexemes(S,"\n"),C}.
902