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