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