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_std_h_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-include_lib("kernel/src/logger_h_common.hrl"). 28-include_lib("kernel/src/logger_olp.hrl"). 29-include_lib("stdlib/include/ms_transform.hrl"). 30-include_lib("kernel/include/file.hrl"). 31 32-define(check_no_log, 33 begin 34 timer:sleep(?IDLE_DETECT_TIME*2), 35 [] = test_server:messages_get() 36 end). 37-define(check(Expected), 38 receive 39 {log,Expected} -> 40 [] = test_server:messages_get() 41 after 5000 -> 42 ct:fail({report_not_received, 43 {line,?LINE}, 44 {expected,Expected}, 45 {got,test_server:messages_get()}}) 46 end). 47 48-define(msg,"Log from "++atom_to_list(?FUNCTION_NAME)++ 49 ":"++integer_to_list(?LINE)). 50-define(bin(Msg), list_to_binary(Msg++"\n")). 51-define(domain,#{domain=>[?MODULE]}). 52 53suite() -> 54 [{timetrap,{seconds,30}}, 55 {ct_hooks,[logger_test_lib]}]. 56 57init_per_suite(Config) -> 58 timer:start(), % to avoid progress report 59 {ok,#{formatter:=OrigFormatter}} = 60 logger:get_handler_config(?STANDARD_HANDLER), 61 [{formatter,OrigFormatter}|Config]. 62 63end_per_suite(Config) -> 64 {OrigMod,OrigConf} = proplists:get_value(formatter,Config), 65 logger:set_handler_config(?STANDARD_HANDLER,formatter,{OrigMod,OrigConf}), 66 ok. 67 68init_per_group(_Group, Config) -> 69 Config. 70 71end_per_group(_Group, _Config) -> 72 ok. 73 74init_per_testcase(reopen_changed_log=TC, Config) -> 75 case os:type() of 76 {win32,_} -> 77 {skip,"This test can only work with inodes, i.e. not on Windows"}; 78 _ -> 79 ct:print("********** ~w **********", [TC]), 80 Config 81 end; 82init_per_testcase(TestHooksCase, Config) when 83 TestHooksCase == write_failure; 84 TestHooksCase == sync_failure -> 85 case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of 86 true -> 87 {skip,"Define the TEST_HOOKS macro to run this test"}; 88 false -> 89 ct:print("********** ~w **********", [TestHooksCase]), 90 Config 91 end; 92init_per_testcase(OPCase, Config) when 93 OPCase == qlen_kill_new; 94 OPCase == restart_after -> 95 case re:run(erlang:system_info(system_version), 96 "dirty-schedulers-TEST", 97 [{capture,none}]) of 98 match -> 99 {skip,"Overload protection test skipped on dirty-schedulers-TEST"}; 100 nomatch -> 101 ct:print("********** ~w **********", [OPCase]), 102 Config 103 end; 104init_per_testcase(TestCase, Config) -> 105 ct:print("********** ~w **********", [TestCase]), 106 Config. 107 108end_per_testcase(Case, Config) -> 109 try apply(?MODULE,Case,[cleanup,Config]) 110 catch error:undef -> ok 111 end, 112 ok. 113 114groups() -> 115 []. 116 117all() -> 118 [add_remove_instance_tty, 119 add_remove_instance_standard_io, 120 add_remove_instance_standard_error, 121 add_remove_instance_custom_device, 122 add_remove_instance_file1, 123 add_remove_instance_file2, 124 add_remove_instance_file3, 125 add_remove_instance_file4, 126 default_formatter, 127 filter_config, 128 errors, 129 formatter_fail, 130 config_fail, 131 crash_std_h_to_file, 132 crash_std_h_to_disk_log, 133 bad_input, 134 reconfig, 135 file_opts, 136 relative_file_path, 137 sync, 138 write_failure, 139 sync_failure, 140 op_switch_to_sync_file, 141 op_switch_to_sync_tty, 142 op_switch_to_drop_file, 143 op_switch_to_drop_tty, 144 op_switch_to_flush_file, 145 op_switch_to_flush_tty, 146 limit_burst_disabled, 147 limit_burst_enabled_one, 148 limit_burst_enabled_period, 149 kill_disabled, 150 qlen_kill_new, 151 qlen_kill_std, 152 mem_kill_new, 153 mem_kill_std, 154 restart_after, 155 handler_requests_under_load, 156 recreate_deleted_log, 157 reopen_changed_log, 158 rotate_size, 159 rotate_size_compressed, 160 rotate_size_reopen, 161 rotate_on_start_compressed, 162 rotation_opts, 163 rotation_opts_restart_handler 164 ]. 165 166add_remove_instance_tty(_Config) -> 167 {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} = 168 logger:add_handler(?MODULE,logger_std_h, 169 #{config => #{type => tty}, 170 filter_default=>log, 171 formatter=>{?MODULE,self()}}), 172 ok. 173 174add_remove_instance_standard_io(_Config) -> 175 add_remove_instance_nofile(standard_io). 176add_remove_instance_standard_io(cleanup,_Config) -> 177 logger_std_h_remove(). 178 179add_remove_instance_custom_device(_Config) -> 180 add_remove_instance_nofile({device,user}). 181add_remove_instance_custom_device(cleanup,_Config) -> 182 logger_std_h_remove(). 183 184add_remove_instance_standard_error(_Config) -> 185 add_remove_instance_nofile(standard_error). 186add_remove_instance_standard_error(cleanup,_Config) -> 187 logger_std_h_remove(). 188 189add_remove_instance_file1(Config) -> 190 Dir = ?config(priv_dir,Config), 191 Log = filename:join(Dir,"stdlog1.txt"), 192 Type = {file,Log}, 193 add_remove_instance_file(Log, Type). 194add_remove_instance_file1(cleanup,_Config) -> 195 logger_std_h_remove(). 196 197add_remove_instance_file2(Config) -> 198 Dir = ?config(priv_dir,Config), 199 Log = filename:join(Dir,"stdlog2.txt"), 200 Type = {file,Log,[raw,append]}, 201 add_remove_instance_file(Log, Type). 202add_remove_instance_file2(cleanup,_Config) -> 203 logger_std_h_remove(). 204 205add_remove_instance_file3(_Config) -> 206 Log = atom_to_list(?MODULE), 207 StdHConfig = #{type=>file}, 208 add_remove_instance_file(Log, StdHConfig). 209add_remove_instance_file3(cleanup,_Config) -> 210 logger_std_h_remove(). 211 212add_remove_instance_file4(Config) -> 213 Dir = ?config(priv_dir,Config), 214 Log = filename:join(Dir,"stdlog4.txt"), 215 StdHConfig = #{file=>Log,modes=>[]}, 216 add_remove_instance_file(Log, StdHConfig). 217add_remove_instance_file4(cleanup,_Config) -> 218 logger_std_h_remove(). 219 220add_remove_instance_file(Log, Type) when not is_map(Type) -> 221 add_remove_instance_file(Log,#{type=>Type}); 222add_remove_instance_file(Log, StdHConfig) when is_map(StdHConfig) -> 223 ok = logger:add_handler(?MODULE, 224 logger_std_h, 225 #{config => StdHConfig, 226 filter_default=>stop, 227 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 228 formatter=>{?MODULE,self()}}), 229 Pid = whereis(h_proc_name()), 230 true = is_pid(Pid), 231 logger:notice(M1=?msg,?domain), 232 ?check(M1), 233 B1 = ?bin(M1), 234 try_read_file(Log, {ok,B1}, filesync_rep_int()), 235 ok = logger:remove_handler(?MODULE), 236 timer:sleep(500), 237 undefined = whereis(h_proc_name()), 238 logger:notice(?msg,?domain), 239 ?check_no_log, 240 try_read_file(Log, {ok,B1}, filesync_rep_int()), 241 ok. 242 243default_formatter(_Config) -> 244 ok = logger:set_handler_config(?STANDARD_HANDLER,formatter, 245 {?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), 246 ct:capture_start(), 247 logger:notice(M1=?msg), 248 timer:sleep(100), 249 ct:capture_stop(), 250 [Msg] = ct:capture_get(), 251 match = re:run(Msg,"=NOTICE REPORT====.*\n"++M1,[{capture,none}]), 252 ok. 253 254filter_config(_Config) -> 255 ok = logger:add_handler(?MODULE,logger_std_h,#{}), 256 {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), 257 HConfig = maps:without([olp],HConfig), 258 259 FakeFullHConfig = HConfig#{olp=>{regname,self(),erlang:make_ref()}}, 260 #{config:=HConfig} = 261 logger_std_h:filter_config(Config#{config=>FakeFullHConfig}), 262 ok. 263 264filter_config(cleanup,_Config) -> 265 logger:remove_handler(?MODULE), 266 ok. 267 268errors(Config) -> 269 Dir = ?config(priv_dir,Config), 270 Log = filename:join(Dir,?FUNCTION_NAME), 271 272 ok = logger:add_handler(?MODULE,logger_std_h,#{}), 273 {error,{already_exist,?MODULE}} = 274 logger:add_handler(?MODULE,logger_std_h,#{}), 275 276 {error,{not_found,no_such_name}} = logger:remove_handler(no_such_name), 277 278 ok = logger:remove_handler(?MODULE), 279 {error,{not_found,?MODULE}} = logger:remove_handler(?MODULE), 280 281 {error, 282 {handler_not_added, 283 {invalid_config,logger_std_h,#{type:=faulty_type}}}} = 284 logger:add_handler(?MODULE,logger_std_h, 285 #{config => #{type => faulty_type}}), 286 287 case os:type() of 288 {win32,_} -> 289 %% No use in testing file access on windows 290 ok; 291 _ -> 292 NoDir = lists:concat(["/",?MODULE,"_dir"]), 293 {error, 294 {handler_not_added,{open_failed,NoDir,Error}}} = 295 logger:add_handler(myh2,logger_std_h, 296 #{config=>#{type=>{file,NoDir}}}), 297 case Error of 298 erofs -> 299 %% Happens on OS X 300 ok; 301 eacces -> 302 ok 303 end 304 end, 305 306 {error, 307 {handler_not_added, 308 {invalid_config,logger_std_h,#{modes:=bad_file_opt}}}} = 309 logger:add_handler(myh3,logger_std_h, 310 #{config=>#{type=>{file,Log,bad_file_opt}}}), 311 312 ok = logger:notice(?msg). 313 314errors(cleanup,_Config) -> 315 logger:remove_handler(?MODULE). 316 317formatter_fail(Config) -> 318 Dir = ?config(priv_dir,Config), 319 Log = filename:join(Dir,?FUNCTION_NAME), 320 321 logger:set_primary_config(level,notice), 322 323 %% no formatter 324 ok = logger:add_handler(?MODULE, 325 logger_std_h, 326 #{config => #{type => {file,Log}}, 327 filter_default=>stop, 328 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), 329 Pid = whereis(h_proc_name()), 330 true = is_pid(Pid), 331 H = logger:get_handler_ids(), 332 true = lists:member(?MODULE,H), 333 334 %% Formatter is added automatically 335 {ok,#{formatter:={logger_formatter,_}}} = logger:get_handler_config(?MODULE), 336 logger:notice(M1=?msg,?domain), 337 Got1 = try_match_file(Log,"[0-9\\+\\-T:\\.]* notice: "++M1,5000), 338 339 ok = logger:set_handler_config(?MODULE,formatter,{nonexistingmodule,#{}}), 340 logger:notice(M2=?msg,?domain), 341 Got2 = try_match_file(Log, 342 escape(Got1)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M2, 343 5000), 344 345 ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,crash}), 346 logger:notice(M3=?msg,?domain), 347 Got3 = try_match_file(Log, 348 escape(Got2)++"[0-9\\+\\-T:\\.]* notice: FORMATTER CRASH: .*"++M3, 349 5000), 350 351 ok = logger:set_handler_config(?MODULE,formatter,{?MODULE,bad_return}), 352 logger:notice(?msg,?domain), 353 try_match_file(Log, 354 escape(Got3)++"FORMATTER ERROR: bad return value", 355 5000), 356 357 %% Check that handler is still alive and was never dead 358 Pid = whereis(h_proc_name()), 359 H = logger:get_handler_ids(), 360 361 ok. 362 363formatter_fail(cleanup,_Config) -> 364 logger:set_primary_config(level,info), 365 logger:remove_handler(?MODULE). 366 367config_fail(_Config) -> 368 {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} = 369 logger:add_handler(?MODULE,logger_std_h, 370 #{config => #{bad => bad}, 371 filter_default=>log, 372 formatter=>{?MODULE,self()}}), 373 {error,{handler_not_added,{invalid_config,logger_std_h, 374 #{restart_type:=bad}}}} = 375 logger:add_handler(?MODULE,logger_std_h, 376 #{config => #{restart_type => bad}, 377 filter_default=>log, 378 formatter=>{?MODULE,self()}}), 379 {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=1}}}} = 380 logger:add_handler(?MODULE,logger_std_h, 381 #{config => #{drop_mode_qlen=>1}}), 382 {error,{handler_not_added,{invalid_olp_levels,#{sync_mode_qlen:=43, 383 drop_mode_qlen:=42}}}} = 384 logger:add_handler(?MODULE,logger_std_h, 385 #{config => #{sync_mode_qlen=>43, 386 drop_mode_qlen=>42}}), 387 {error,{handler_not_added,{invalid_olp_levels,#{drop_mode_qlen:=43, 388 flush_qlen:=42}}}} = 389 logger:add_handler(?MODULE,logger_std_h, 390 #{config => #{drop_mode_qlen=>43, 391 flush_qlen=>42}}), 392 393 ok = logger:add_handler(?MODULE,logger_std_h, 394 #{filter_default=>log, 395 formatter=>{?MODULE,self()}}), 396 {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} = 397 logger:set_handler_config(?MODULE,config, 398 #{type=>{file,"file"}}), 399 400 {error,{invalid_olp_levels,_}} = 401 logger:set_handler_config(?MODULE,config, 402 #{sync_mode_qlen=>100, 403 flush_qlen=>99}), 404 {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} = 405 logger:set_handler_config(?MODULE, config, 406 #{filesync_rep_int => 2000}), 407 408 %% Read-only fields may (accidentially) be included in the change, 409 %% but it won't take effect 410 {ok,C} = logger:get_handler_config(?MODULE), 411 ok = logger:set_handler_config(?MODULE,config,#{olp=>dummyvalue}), 412 {ok,C} = logger:get_handler_config(?MODULE), 413 414 ok. 415 416config_fail(cleanup,_Config) -> 417 logger:remove_handler(?MODULE). 418 419crash_std_h_to_file(Config) -> 420 Dir = ?config(priv_dir,Config), 421 Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), 422 crash_std_h(Config,?FUNCTION_NAME, 423 [{handler,default,logger_std_h, 424 #{ config => #{ type => {file, Log} }}}], 425 file, Log). 426crash_std_h_to_file(cleanup,_Config) -> 427 crash_std_h(cleanup). 428 429crash_std_h_to_disk_log(Config) -> 430 Dir = ?config(priv_dir,Config), 431 Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), 432 crash_std_h(Config,?FUNCTION_NAME, 433 [{handler,default,logger_disk_log_h, 434 #{ config => #{ file => Log }}}], 435 disk_log,Log). 436crash_std_h_to_disk_log(cleanup,_Config) -> 437 crash_std_h(cleanup). 438 439crash_std_h(Config,Func,Var,Type,Log) -> 440 Dir = ?config(priv_dir,Config), 441 SysConfig = filename:join(Dir,lists:concat([?MODULE,"_",Func,".config"])), 442 ok = file:write_file(SysConfig, io_lib:format("[{kernel,[{logger,~p}]}].",[Var])), 443 Pa = filename:dirname(code:which(?MODULE)), 444 Name = lists:concat([?MODULE,"_",Func]), 445 Args = lists:concat([" -config ",filename:rootname(SysConfig)," -pa ",Pa]), 446 ct:pal("Starting ~p with ~tp", [Name,Args]), 447 %% Start a node which prints kernel logs to the destination specified by Type 448 {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), 449 HProcName = 450 case Type of 451 file -> ?name_to_reg_name(logger_std_h,?STANDARD_HANDLER); 452 disk_log -> ?name_to_reg_name(logger_disk_log_h,?STANDARD_HANDLER) 453 end, 454 Pid = rpc:call(Node,erlang,whereis,[HProcName]), 455 ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, 456 {?MODULE,self()}]), 457 ok = log_on_remote_node(Node,"dummy1"), 458 ?check("dummy1"), 459 {ok,Bin1} = sync_and_read(Node,Type,Log), 460 <<"dummy1\n">> = binary:part(Bin1,{byte_size(Bin1),-7}), 461 462 %% Kill the logger_std_h process 463 exit(Pid, kill), 464 465 %% Wait a bit, then check that it is gone 466 timer:sleep(2000), 467 undefined = rpc:call(Node,erlang,whereis,[HProcName]), 468 469 %% Check that file is not empty 470 {ok,Bin2} = sync_and_read(Node,Type,Log), 471 <<"dummy1\n">> = binary:part(Bin2,{byte_size(Bin2),-7}), 472 ok. 473 474%% Can not use rpc:call here, since the code would execute on a 475%% process with group_leader on this (the calling) node, and thus 476%% logger would send the log event to the logger process here instead 477%% of logging it itself. 478log_on_remote_node(Node,Msg) -> 479 Pid = self(), 480 _ = spawn_link(Node, 481 fun() -> erlang:group_leader(whereis(user),self()), 482 logger:notice(Msg), 483 Pid ! done 484 end), 485 receive done -> ok end, 486 ok. 487 488 489crash_std_h(cleanup) -> 490 Nodes = nodes(), 491 [test_server:stop_node(Node) || Node <- Nodes]. 492 493sync_and_read(Node,disk_log,Log) -> 494 rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]), 495 case file:read_file(Log ++ ".1") of 496 {ok,<<>>} -> 497 timer:sleep(5000), 498 file:read_file(Log ++ ".1"); 499 Ok -> 500 Ok 501 end; 502sync_and_read(Node,file,Log) -> 503 rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), 504 case file:read_file(Log) of 505 {ok,<<>>} -> 506 timer:sleep(5000), 507 file:read_file(Log); 508 Ok -> 509 Ok 510 end. 511 512bad_input(_Config) -> 513 {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"). 514 515reconfig(Config) -> 516 Dir = ?config(priv_dir,Config), 517 ok = logger:add_handler(?MODULE, 518 logger_std_h, 519 #{config => #{type => standard_io}, 520 filter_default=>log, 521 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 522 formatter=>{?MODULE,self()}}), 523 #{%id := ?MODULE, 524 cb_state:=#{handler_state := #{type := standard_io, 525 file_ctrl_pid := FileCtrlPid}, 526 filesync_repeat_interval := no_repeat}, 527 sync_mode_qlen := ?SYNC_MODE_QLEN, 528 drop_mode_qlen := ?DROP_MODE_QLEN, 529 flush_qlen := ?FLUSH_QLEN, 530 burst_limit_enable := ?BURST_LIMIT_ENABLE, 531 burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, 532 burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, 533 overload_kill_enable := ?OVERLOAD_KILL_ENABLE, 534 overload_kill_qlen := ?OVERLOAD_KILL_QLEN, 535 overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, 536 overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER} = 537 logger_olp:info(h_proc_name()), 538 539 {ok, 540 #{config:= 541 #{type := standard_io, 542 sync_mode_qlen := ?SYNC_MODE_QLEN, 543 drop_mode_qlen := ?DROP_MODE_QLEN, 544 flush_qlen := ?FLUSH_QLEN, 545 burst_limit_enable := ?BURST_LIMIT_ENABLE, 546 burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, 547 burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, 548 overload_kill_enable := ?OVERLOAD_KILL_ENABLE, 549 overload_kill_qlen := ?OVERLOAD_KILL_QLEN, 550 overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, 551 overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, 552 filesync_repeat_interval := no_repeat} = 553 DefaultHConf}} 554 = logger:get_handler_config(?MODULE), 555 556 ok = logger:set_handler_config(?MODULE, config, 557 #{sync_mode_qlen => 1, 558 drop_mode_qlen => 2, 559 flush_qlen => 3, 560 burst_limit_enable => false, 561 burst_limit_max_count => 10, 562 burst_limit_window_time => 10, 563 overload_kill_enable => true, 564 overload_kill_qlen => 100000, 565 overload_kill_mem_size => 10000000, 566 overload_kill_restart_after => infinity, 567 filesync_repeat_interval => 5000}), 568 #{%id := ?MODULE, 569 cb_state := #{handler_state := #{type := standard_io, 570 file_ctrl_pid := FileCtrlPid}, 571 filesync_repeat_interval := no_repeat}, 572 sync_mode_qlen := 1, 573 drop_mode_qlen := 2, 574 flush_qlen := 3, 575 burst_limit_enable := false, 576 burst_limit_max_count := 10, 577 burst_limit_window_time := 10, 578 overload_kill_enable := true, 579 overload_kill_qlen := 100000, 580 overload_kill_mem_size := 10000000, 581 overload_kill_restart_after := infinity} = logger_olp:info(h_proc_name()), 582 583 {ok,#{config := 584 #{type := standard_io, 585 sync_mode_qlen := 1, 586 drop_mode_qlen := 2, 587 flush_qlen := 3, 588 burst_limit_enable := false, 589 burst_limit_max_count := 10, 590 burst_limit_window_time := 10, 591 overload_kill_enable := true, 592 overload_kill_qlen := 100000, 593 overload_kill_mem_size := 10000000, 594 overload_kill_restart_after := infinity, 595 filesync_repeat_interval := no_repeat} = HConf}} = 596 logger:get_handler_config(?MODULE), 597 598 ok = logger:update_handler_config(?MODULE, config, 599 #{flush_qlen => ?FLUSH_QLEN}), 600 {ok,#{config:=C1}} = logger:get_handler_config(?MODULE), 601 ct:log("C1: ~p",[C1]), 602 C1 = HConf#{flush_qlen => ?FLUSH_QLEN}, 603 604 ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), 605 {ok,#{config:=C2}} = logger:get_handler_config(?MODULE), 606 ct:log("C2: ~p",[C2]), 607 C2 = DefaultHConf#{sync_mode_qlen => 1}, 608 609 ok = logger:set_handler_config(?MODULE, config, #{drop_mode_qlen => 100}), 610 {ok,#{config:=C3}} = logger:get_handler_config(?MODULE), 611 ct:log("C3: ~p",[C3]), 612 C3 = DefaultHConf#{drop_mode_qlen => 100}, 613 614 ok = logger:update_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), 615 {ok,#{config:=C4}} = logger:get_handler_config(?MODULE), 616 ct:log("C4: ~p",[C4]), 617 C4 = DefaultHConf#{sync_mode_qlen => 1, 618 drop_mode_qlen => 100}, 619 620 ok = logger:remove_handler(?MODULE), 621 622 File = filename:join(Dir,lists:concat([?FUNCTION_NAME,".log"])), 623 ok = logger:add_handler(?MODULE, 624 logger_std_h, 625 #{config => #{type => {file,File}}, 626 filter_default=>log, 627 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 628 formatter=>{?MODULE,self()}}), 629 630 {ok,#{config:=#{filesync_repeat_interval:=FSI}=FileHConfig}} = 631 logger:get_handler_config(?MODULE), 632 ok = logger:update_handler_config(?MODULE,config, 633 #{filesync_repeat_interval=>FSI+2000}), 634 {ok,#{config:=C5}} = logger:get_handler_config(?MODULE), 635 ct:log("C5: ~p",[C5]), 636 C5 = FileHConfig#{filesync_repeat_interval=>FSI+2000}, 637 638 %% You are not allowed to actively set 'type' in runtime, since 639 %% this is a write once field. 640 {error, {illegal_config_change,logger_std_h,_,_}} = 641 logger:set_handler_config(?MODULE,config,#{type=>standard_io}), 642 {ok,#{config:=C6}} = logger:get_handler_config(?MODULE), 643 ct:log("C6: ~p",[C6]), 644 C6 = C5, 645 646 %% ... but if you don't specify 'type', then set_handler_config shall 647 %% NOT reset it to its default value 648 ok = logger:set_handler_config(?MODULE,config,#{sync_mode_qlen=>1}), 649 {ok,#{config:=C7}} = logger:get_handler_config(?MODULE), 650 ct:log("C7: ~p",[C7]), 651 C7 = FileHConfig#{sync_mode_qlen=>1}, 652 ok. 653 654reconfig(cleanup, _Config) -> 655 logger:remove_handler(?MODULE). 656 657 658file_opts(Config) -> 659 Dir = ?config(priv_dir,Config), 660 Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), 661 MissingOpts = [raw], 662 Type1 = {file,Log,MissingOpts}, 663 ok = logger:add_handler(?MODULE, logger_std_h, 664 #{config => #{type => Type1}}), 665 {ok,#{config:=#{type:=file,file:=Log,modes:=Modes1}}} = 666 logger:get_handler_config(?MODULE), 667 [append,delayed_write,raw] = lists:sort(Modes1), 668 ok = logger:remove_handler(?MODULE), 669 670 OkFileOpts = [raw,append], 671 OkType = {file,Log,OkFileOpts}, 672 ok = logger:add_handler(?MODULE, 673 logger_std_h, 674 #{config => #{type => OkType}, % old format 675 filter_default=>log, 676 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 677 formatter=>{?MODULE,self()}}), 678 679 ModOpts = [delayed_write|OkFileOpts], 680 #{cb_state := #{handler_state := #{type:=file, 681 file:=Log, 682 modes:=ModOpts}}} = 683 logger_olp:info(h_proc_name()), 684 {ok,#{config := #{type:=file, 685 file:=Log, 686 modes:=ModOpts}}} = logger:get_handler_config(?MODULE), 687 ok = logger:remove_handler(?MODULE), 688 689 ok = logger:add_handler(?MODULE, 690 logger_std_h, 691 #{config => #{type => file, 692 file => Log, 693 modes => OkFileOpts}, % new format 694 filter_default=>log, 695 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 696 formatter=>{?MODULE,self()}}), 697 698 #{cb_state := #{handler_state := #{type:=file, 699 file:=Log, 700 modes:=ModOpts}}} = 701 logger_olp:info(h_proc_name()), 702 {ok,#{config := #{type:=file, 703 file:=Log, 704 modes:=ModOpts}}} = 705 logger:get_handler_config(?MODULE), 706 logger:notice(M1=?msg,?domain), 707 ?check(M1), 708 B1 = ?bin(M1), 709 try_read_file(Log, {ok,B1}, filesync_rep_int()), 710 ok. 711file_opts(cleanup, _Config) -> 712 logger:remove_handler(?MODULE). 713 714relative_file_path(_Config) -> 715 {ok,Dir} = file:get_cwd(), 716 AbsName1 = filename:join(Dir,?MODULE), 717 ok = logger:add_handler(?MODULE, 718 logger_std_h, 719 #{config => #{type=>file}, 720 filter_default=>log, 721 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 722 formatter=>{?MODULE,self()}}), 723 #{cb_state := #{handler_state := #{file:=AbsName1}}} = 724 logger_olp:info(h_proc_name()), 725 {ok,#{config := #{file:=AbsName1}}} = 726 logger:get_handler_config(?MODULE), 727 ok = logger:remove_handler(?MODULE), 728 729 RelName2 = filename:join(atom_to_list(?FUNCTION_NAME), 730 lists:concat([?FUNCTION_NAME,".log"])), 731 AbsName2 = filename:join(Dir,RelName2), 732 ok = logger:add_handler(?MODULE, 733 logger_std_h, 734 #{config => #{file => RelName2}, 735 filter_default=>log, 736 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 737 formatter=>{?MODULE,self()}}), 738 #{cb_state := #{handler_state := #{file:=AbsName2}}} = 739 logger_olp:info(h_proc_name()), 740 {ok,#{config := #{file:=AbsName2}}} = 741 logger:get_handler_config(?MODULE), 742 logger:notice(M1=?msg,?domain), 743 ?check(M1), 744 B1 = ?bin(M1), 745 try_read_file(AbsName2, {ok,B1}, filesync_rep_int()), 746 747 ok = file:set_cwd(".."), 748 logger:notice(M2=?msg,?domain), 749 ?check(M2), 750 B20 = ?bin(M2), 751 B2 = <<B1/binary,B20/binary>>, 752 try_read_file(AbsName2, {ok,B2}, filesync_rep_int()), 753 754 {error,_} = logger:update_handler_config(?MODULE,config,#{file=>RelName2}), 755 ok = logger:update_handler_config(?MODULE,config,#{file=>AbsName2}), 756 ok = file:set_cwd(Dir), 757 ok = logger:update_handler_config(?MODULE,config,#{file=>RelName2}), 758 ok. 759relative_file_path(cleanup,_Config) -> 760 logger:remove_handler(?MODULE). 761 762 763sync(Config) -> 764 Dir = ?config(priv_dir,Config), 765 Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), 766 Type = {file,Log}, 767 ok = logger:add_handler(?MODULE, 768 logger_std_h, 769 #{config => #{type => Type, 770 file_check => 10000}, 771 filter_default=>log, 772 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 773 formatter=>{?MODULE,nl}}), 774 775 %% check repeated filesync happens 776 start_tracer([{logger_std_h, write_to_dev, 2}, 777 {file, datasync, 1}], 778 [{logger_std_h, write_to_dev, <<"first\n">>}, 779 {file,datasync}]), 780 781 logger:notice("first", ?domain), 782 %% wait for automatic filesync 783 check_tracer(filesync_rep_int()*2), 784 785 %% check that explicit filesync is only done once 786 start_tracer([{logger_std_h, write_to_dev, 2}, 787 {file, datasync, 1}], 788 [{logger_std_h, write_to_dev, <<"second\n">>}, 789 {file,datasync}, 790 {no_more,500} 791 ]), 792 logger:notice("second", ?domain), 793 %% do explicit sync 794 logger_std_h:filesync(?MODULE), 795 %% a second sync should be ignored 796 logger_std_h:filesync(?MODULE), 797 check_tracer(100), 798 799 %% check that if there's no repeated filesync active, 800 %% a filesync is still performed when handler goes idle 801 ok = logger:update_handler_config(?MODULE, config, 802 #{filesync_repeat_interval => no_repeat}), 803 no_repeat = maps:get(filesync_repeat_interval, 804 maps:get(cb_state, logger_olp:info(h_proc_name()))), 805 start_tracer([{logger_std_h, write_to_dev, 2}, 806 {file, datasync, 1}], 807 [{logger_std_h, write_to_dev, <<"third\n">>}, 808 {file,datasync}, 809 {logger_std_h, write_to_dev, <<"fourth\n">>}, 810 {file,datasync}]), 811 logger:notice("third", ?domain), 812 %% wait for automatic filesync 813 timer:sleep(?IDLE_DETECT_TIME*2), 814 logger:notice("fourth", ?domain), 815 %% wait for automatic filesync 816 check_tracer(?IDLE_DETECT_TIME*2), 817 818 %% switch repeated filesync on and verify that the looping works 819 SyncInt = 1000, 820 WaitT = 4500, 821 OneSync = {logger_h_common,handle_cast,repeated_filesync}, 822 %% receive 1 repeated_filesync per sec 823 start_tracer([{{logger_h_common,handle_cast,2}, 824 [{[repeated_filesync,'_'],[],[]}]}], 825 [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), 826 827 ok = logger:update_handler_config(?MODULE, config, 828 #{filesync_repeat_interval => SyncInt}), 829 SyncInt = maps:get(filesync_repeat_interval, 830 maps:get(cb_state,logger_olp:info(h_proc_name()))), 831 timer:sleep(WaitT), 832 ok = logger:update_handler_config(?MODULE, config, 833 #{filesync_repeat_interval => no_repeat}), 834 check_tracer(100), 835 ok. 836sync(cleanup, _Config) -> 837 stop_clear(), 838 logger:remove_handler(?MODULE). 839 840write_failure(Config) -> 841 Dir = ?config(priv_dir, Config), 842 File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), 843 Log = filename:join(Dir, File), 844 Node = start_std_h_on_new_node(Config, Log), 845 false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), 846 rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), 847 rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), 848 rpc:call(Node, ?MODULE, set_result, [file_write,ok]), 849 850 ok = log_on_remote_node(Node, "Logged1"), 851 rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), 852 ?check_no_log, 853 try_read_file(Log, {ok,<<"Logged1\n">>}, filesync_rep_int()), 854 855 rpc:call(Node, ?MODULE, set_result, [file_write,{error,terminated}]), 856 ok = log_on_remote_node(Node, "Cause simple error printout"), 857 858 ?check({error,{?STANDARD_HANDLER,write,Log,{error,terminated}}}), 859 860 ok = log_on_remote_node(Node, "No second error printout"), 861 ?check_no_log, 862 863 rpc:call(Node, ?MODULE, set_result, [file_write,{error,eacces}]), 864 ok = log_on_remote_node(Node, "Cause simple error printout"), 865 ?check({error,{?STANDARD_HANDLER,write,Log,{error,eacces}}}), 866 867 rpc:call(Node, ?MODULE, set_result, [file_write,ok]), 868 ok = log_on_remote_node(Node, "Logged2"), 869 rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), 870 ?check_no_log, 871 try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, filesync_rep_int()), 872 ok. 873write_failure(cleanup, _Config) -> 874 Nodes = nodes(), 875 [test_server:stop_node(Node) || Node <- Nodes]. 876 877sync_failure(Config) -> 878 Dir = ?config(priv_dir, Config), 879 File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), 880 Log = filename:join(Dir, File), 881 Node = start_std_h_on_new_node(Config, Log), 882 false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), 883 rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), 884 rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), 885 rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), 886 887 SyncInt = 500, 888 ok = rpc:call(Node, logger, update_handler_config, 889 [?STANDARD_HANDLER, config, 890 #{filesync_repeat_interval => SyncInt}]), 891 892 ok = log_on_remote_node(Node, "Logged1"), 893 ?check_no_log, 894 895 rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,terminated}]), 896 ok = log_on_remote_node(Node, "Cause simple error printout"), 897 898 ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,terminated}}}), 899 900 ok = log_on_remote_node(Node, "No second error printout"), 901 ?check_no_log, 902 903 rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,eacces}]), 904 ok = log_on_remote_node(Node, "Cause simple error printout"), 905 ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,eacces}}}), 906 907 rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), 908 ok = log_on_remote_node(Node, "Logged2"), 909 ?check_no_log, 910 ok. 911sync_failure(cleanup, _Config) -> 912 Nodes = nodes(), 913 [test_server:stop_node(Node) || Node <- Nodes]. 914 915start_std_h_on_new_node(Config, Log) -> 916 {ok,_,Node} = 917 logger_test_lib:setup( 918 Config, 919 [{logger,[{handler,default,logger_std_h, 920 #{ config => #{ type => {file,Log}}}}]}]), 921 ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, 922 {?MODULE,nl}]), 923 Node. 924 925%% functions for test hook macros to be called by rpc 926set_internal_log(_Mod, _Func) -> 927 ?set_internal_log({_Mod,_Func}). 928set_result(_Op, _Result) -> 929 ?set_result(_Op, _Result). 930set_defaults() -> 931 ?set_defaults(). 932 933%% internal log function that sends the term to the test case process 934internal_log(Type, Term) -> 935 [{tester,Tester}] = ets:lookup(?TEST_HOOKS_TAB, tester), 936 Tester ! {log,{Type,Term}}, 937 logger:internal_log(Type, Term), 938 ok. 939 940 941%%%----------------------------------------------------------------- 942%%% Overload protection tests 943 944op_switch_to_sync_file(Config) -> 945 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 946 NumOfReqs = 500, 947 NewHConfig = 948 HConfig#{config => StdHConfig#{sync_mode_qlen => 2, 949 drop_mode_qlen => NumOfReqs+1, 950 flush_qlen => 2*NumOfReqs, 951 burst_limit_enable => false}}, 952 ok = logger:update_handler_config(?MODULE, NewHConfig), 953 %% TRecvPid = start_op_trace(), 954 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 955 Lines = count_lines(Log), 956 %% true = analyse_trace(TRecvPid, 957 %% fun(Events) -> find_mode(async,Events) end), 958 %% true = analyse_trace(TRecvPid, 959 %% fun(Events) -> find_mode(sync,Events) end), 960 %% true = analyse_trace(TRecvPid, 961 %% fun(Events) -> find_switch(async,sync,Events) end), 962 %% false = analyse_trace(TRecvPid, 963 %% fun(Events) -> find_mode(drop,Events) end), 964 %% false = analyse_trace(TRecvPid, 965 %% fun(Events) -> find_mode(flush,Events) end), 966 %% stop_op_trace(TRecvPid), 967 NumOfReqs = Lines, 968 ok = file_delete(Log), 969 ok. 970op_switch_to_sync_file(cleanup, _Config) -> 971 ok = stop_handler(?MODULE). 972 973op_switch_to_sync_tty(Config) -> 974 {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), 975 NumOfReqs = 500, 976 NewHConfig = 977 HConfig#{config => StdHConfig#{sync_mode_qlen => 3, 978 drop_mode_qlen => NumOfReqs+1, 979 flush_qlen => 2*NumOfReqs, 980 burst_limit_enable => false}}, 981 ok = logger:update_handler_config(?MODULE, NewHConfig), 982 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 983 ok. 984op_switch_to_sync_tty(cleanup, _Config) -> 985 ok = stop_handler(?MODULE). 986 987op_switch_to_drop_file() -> 988 [{timetrap,{seconds,180}}]. 989op_switch_to_drop_file(Config) -> 990 Test = 991 fun() -> 992 {Log,HConfig,StdHConfig} = 993 start_handler(?MODULE, ?FUNCTION_NAME, Config), 994 NumOfReqs = 300, 995 Procs = 2, 996 Bursts = 10, 997 NewHConfig = 998 HConfig#{config => 999 StdHConfig#{sync_mode_qlen => 1, 1000 drop_mode_qlen => 2, 1001 flush_qlen => 1002 Procs*NumOfReqs*Bursts, 1003 burst_limit_enable => false}}, 1004 ok = logger:update_handler_config(?MODULE, NewHConfig), 1005 %% It sometimes happens that the handler gets the 1006 %% requests in a slow enough pace so that dropping 1007 %% never occurs. Therefore, lets generate a number of 1008 %% bursts to increase the chance of message buildup. 1009 [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || 1010 _ <- lists:seq(1, Bursts)], 1011 Logged = count_lines(Log), 1012 ok = stop_handler(?MODULE), 1013 ct:pal("Number of messages dropped = ~w (~w)", 1014 [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), 1015 true = (Logged < (Procs*NumOfReqs*Bursts)), 1016 true = (Logged > 0), 1017 _ = file_delete(Log), 1018 ok 1019 end, 1020 %% As it's tricky to get the timing right in only one go, we perform the 1021 %% test repeatedly, hoping that will generate a successful result. 1022 case repeat_until_ok(Test, 10) of 1023 {ok,{Failures,_Result}} -> 1024 ct:log("Failed ~w times before success!", [Failures]); 1025 {fails,Reason} -> 1026 ct:fail(Reason) 1027 end. 1028op_switch_to_drop_file(cleanup, _Config) -> 1029 _ = stop_handler(?MODULE). 1030 1031op_switch_to_drop_tty(Config) -> 1032 {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), 1033 NumOfReqs = 300, 1034 Procs = 2, 1035 NewHConfig = 1036 HConfig#{config => StdHConfig#{sync_mode_qlen => 1, 1037 drop_mode_qlen => 2, 1038 flush_qlen => 1039 Procs*NumOfReqs+1, 1040 burst_limit_enable => false}}, 1041 ok = logger:update_handler_config(?MODULE, NewHConfig), 1042 send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), 1043 ok. 1044op_switch_to_drop_tty(cleanup, _Config) -> 1045 ok = stop_handler(?MODULE). 1046 1047op_switch_to_flush_file() -> 1048 [{timetrap,{minutes,5}}]. 1049op_switch_to_flush_file(Config) -> 1050 Test = 1051 fun() -> 1052 {Log,HConfig,StdHConfig} = 1053 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1054 1055 %% NOTE: it's important that both async and sync 1056 %% requests have been queued when the flush happens 1057 %% (verify with coverage of flush_log_requests/2) 1058 1059 NewHConfig = 1060 HConfig#{config => 1061 StdHConfig#{sync_mode_qlen => 2, 1062 %% disable drop mode 1063 drop_mode_qlen => 300, 1064 flush_qlen => 300, 1065 burst_limit_enable => false}}, 1066 ok = logger:update_handler_config(?MODULE, NewHConfig), 1067 NumOfReqs = 1500, 1068 Procs = 10, 1069 Bursts = 10, 1070 %% It sometimes happens that the handler either gets 1071 %% the requests in a slow enough pace so that flushing 1072 %% never occurs, or it gets all messages at once, 1073 %% causing all messages to get flushed (no dropping of 1074 %% sync messages gets tested). Therefore, lets 1075 %% generate a number of bursts to increase the chance 1076 %% of message buildup in some random fashion. 1077 [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice) || 1078 _ <- lists:seq(1,Bursts)], 1079 Logged = count_lines(Log), 1080 ok = stop_handler(?MODULE), 1081 ct:pal("Number of messages flushed/dropped = ~w (~w)", 1082 [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), 1083 true = (Logged < (NumOfReqs*Procs*Bursts)), 1084 true = (Logged > 0), 1085 _ = file_delete(Log), 1086 ok 1087 end, 1088 %% As it's tricky to get the timing right in only one go, we perform the 1089 %% test repeatedly, hoping that will generate a successful result. 1090 case repeat_until_ok(Test, 10) of 1091 {ok,{Failures,_Result}} -> 1092 ct:log("Failed ~w times before success!", [Failures]); 1093 {fails,Reason} -> 1094 ct:fail(Reason) 1095 end. 1096op_switch_to_flush_file(cleanup, _Config) -> 1097 _ = stop_handler(?MODULE). 1098 1099op_switch_to_flush_tty() -> 1100 [{timetrap,{minutes,5}}]. 1101op_switch_to_flush_tty(Config) -> 1102 {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), 1103 1104 %% it's important that both async and sync requests have been queued 1105 %% when the flush happens (verify with coverage of flush_log_requests/2) 1106 1107 NewHConfig = 1108 HConfig#{config => StdHConfig#{sync_mode_qlen => 2, 1109 %% disable drop mode 1110 drop_mode_qlen => 100, 1111 flush_qlen => 100, 1112 burst_limit_enable => false}}, 1113 ok = logger:update_handler_config(?MODULE, NewHConfig), 1114 NumOfReqs = 1000, 1115 Procs = 100, 1116 send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), 1117 ok. 1118op_switch_to_flush_tty(cleanup, _Config) -> 1119 ok = stop_handler(?MODULE). 1120 1121limit_burst_disabled(Config) -> 1122 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1123 NewHConfig = 1124 HConfig#{config => StdHConfig#{burst_limit_enable => false, 1125 burst_limit_max_count => 10, 1126 burst_limit_window_time => 2000, 1127 drop_mode_qlen => 200, 1128 flush_qlen => 300}}, 1129 ok = logger:update_handler_config(?MODULE, NewHConfig), 1130 NumOfReqs = 100, 1131 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1132 Logged = count_lines(Log), 1133 ct:pal("Number of messages logged = ~w", [Logged]), 1134 NumOfReqs = Logged, 1135 ok = file_delete(Log), 1136 ok. 1137limit_burst_disabled(cleanup, _Config) -> 1138 ok = stop_handler(?MODULE). 1139 1140limit_burst_enabled_one(Config) -> 1141 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1142 ReqLimit = 10, 1143 NewHConfig = 1144 HConfig#{config => StdHConfig#{burst_limit_enable => true, 1145 burst_limit_max_count => ReqLimit, 1146 burst_limit_window_time => 2000, 1147 drop_mode_qlen => 200, 1148 flush_qlen => 300}}, 1149 ok = logger:update_handler_config(?MODULE, NewHConfig), 1150 NumOfReqs = 100, 1151 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1152 Logged = count_lines(Log), 1153 ct:pal("Number of messages logged = ~w", [Logged]), 1154 ReqLimit = Logged, 1155 ok = file_delete(Log), 1156 ok. 1157limit_burst_enabled_one(cleanup, _Config) -> 1158 ok = stop_handler(?MODULE). 1159 1160limit_burst_enabled_period(Config) -> 1161 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1162 ReqLimit = 10, 1163 BurstTWin = 1000, 1164 NewHConfig = 1165 HConfig#{config => StdHConfig#{burst_limit_enable => true, 1166 burst_limit_max_count => ReqLimit, 1167 burst_limit_window_time => BurstTWin, 1168 drop_mode_qlen => 20000, 1169 flush_qlen => 20001}}, 1170 ok = logger:update_handler_config(?MODULE, NewHConfig), 1171 1172 Windows = 3, 1173 Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), 1174 Logged = count_lines(Log), 1175 ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", 1176 [Sent,Logged]), 1177 true = (Logged > (ReqLimit*Windows)) andalso 1178 (Logged < (ReqLimit*(Windows+2))), 1179 ok = file_delete(Log), 1180 ok. 1181limit_burst_enabled_period(cleanup, _Config) -> 1182 ok = stop_handler(?MODULE). 1183 1184kill_disabled(Config) -> 1185 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1186 NewHConfig = 1187 HConfig#{config=>StdHConfig#{overload_kill_enable=>false, 1188 overload_kill_qlen=>10, 1189 overload_kill_mem_size=>100}}, 1190 ok = logger:update_handler_config(?MODULE, NewHConfig), 1191 NumOfReqs = 100, 1192 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1193 Logged = count_lines(Log), 1194 ct:pal("Number of messages logged = ~w", [Logged]), 1195 ok = file_delete(Log), 1196 true = is_pid(whereis(h_proc_name())), 1197 ok. 1198kill_disabled(cleanup, _Config) -> 1199 ok = stop_handler(?MODULE). 1200 1201qlen_kill_new(Config) -> 1202 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1203 Pid0 = whereis(h_proc_name()), 1204 {_,Mem0} = process_info(Pid0, memory), 1205 RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, 1206 NewHConfig = 1207 HConfig#{config=>StdHConfig#{overload_kill_enable=>true, 1208 overload_kill_qlen=>10, 1209 overload_kill_mem_size=>Mem0+50000, 1210 overload_kill_restart_after=>RestartAfter}}, 1211 ok = logger:update_handler_config(?MODULE, NewHConfig), 1212 MRef = erlang:monitor(process, Pid0), 1213 NumOfReqs = 100, 1214 Procs = 4, 1215 send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), 1216 %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1217 receive 1218 {'DOWN', MRef, _, _, Info} -> 1219 case Info of 1220 {shutdown,{overloaded,QLen,Mem}} -> 1221 ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); 1222 killed -> 1223 ct:pal("Slow shutdown, handler process was killed!", []) 1224 end, 1225 file_delete(Log), 1226 {ok,_} = wait_for_process_up(RestartAfter * 3), 1227 ok 1228 after 1229 5000 -> 1230 Info = logger_olp:info(h_proc_name()), 1231 ct:pal("Handler state = ~p", [Info]), 1232 ct:fail("Handler not dead! It should not have survived this!") 1233 end. 1234qlen_kill_new(cleanup, _Config) -> 1235 ok = stop_handler(?MODULE). 1236 1237%% choke the standard handler on remote node to verify the termination 1238%% works as expected 1239qlen_kill_std(_Config) -> 1240 %%! HERE 1241 %% Dir = ?config(priv_dir, Config), 1242 %% File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), 1243 %% Log = filename:join(Dir, File), 1244 %% Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), 1245 %% ok = rpc:call(Node, logger, update_handler_config, 1246 %% [?STANDARD_HANDLER, config, 1247 %% #{overload_kill_enable=>true, 1248 %% overload_kill_qlen=>10, 1249 %% overload_kill_mem_size=>100000}]), 1250 {skip,"Not done yet"}. 1251 1252mem_kill_new(Config) -> 1253 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1254 Pid0 = whereis(h_proc_name()), 1255 {_,Mem0} = process_info(Pid0, memory), 1256 RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, 1257 NewHConfig = 1258 HConfig#{config=>StdHConfig#{overload_kill_enable=>true, 1259 overload_kill_qlen=>50000, 1260 overload_kill_mem_size=>Mem0+500, 1261 overload_kill_restart_after=>RestartAfter}}, 1262 ok = logger:update_handler_config(?MODULE, NewHConfig), 1263 MRef = erlang:monitor(process, Pid0), 1264 NumOfReqs = 100, 1265 Procs = 4, 1266 send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), 1267 %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1268 receive 1269 {'DOWN', MRef, _, _, Info} -> 1270 case Info of 1271 {shutdown,{overloaded,QLen,Mem}} -> 1272 ct:pal("Terminated with qlen = ~w, mem = ~w", [QLen,Mem]); 1273 killed -> 1274 ct:pal("Slow shutdown, handler process was killed!", []) 1275 end, 1276 file_delete(Log), 1277 {ok,_} = wait_for_process_up(RestartAfter * 3), 1278 ok 1279 after 1280 5000 -> 1281 Info = logger_olp:info(h_proc_name()), 1282 ct:pal("Handler state = ~p", [Info]), 1283 ct:fail("Handler not dead! It should not have survived this!") 1284 end. 1285mem_kill_new(cleanup, _Config) -> 1286 ok = stop_handler(?MODULE). 1287 1288%% choke the standard handler on remote node to verify the termination 1289%% works as expected 1290mem_kill_std(_Config) -> 1291 {skip,"Not done yet"}. 1292 1293restart_after() -> 1294 [{timetrap,{minutes,2}}]. 1295restart_after(Config) -> 1296 {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1297 NewHConfig1 = 1298 HConfig#{config=>StdHConfig#{overload_kill_enable=>true, 1299 overload_kill_qlen=>10, 1300 overload_kill_restart_after=>infinity}}, 1301 ok = logger:update_handler_config(?MODULE, NewHConfig1), 1302 MRef1 = erlang:monitor(process, whereis(h_proc_name())), 1303 %% kill handler 1304 send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), 1305 receive 1306 {'DOWN', MRef1, _, _, _Reason1} -> 1307 file_delete(Log), 1308 error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3), 1309 ok 1310 after 1311 5000 -> 1312 Info1 = logger_olp:info(h_proc_name()), 1313 ct:pal("Handler state = ~p", [Info1]), 1314 ct:fail("Handler not dead! It should not have survived this!") 1315 end, 1316 1317 {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), 1318 RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, 1319 1320 NewHConfig2 = 1321 HConfig#{config=>StdHConfig#{overload_kill_enable=>true, 1322 overload_kill_qlen=>10, 1323 overload_kill_restart_after=>RestartAfter}}, 1324 ok = logger:update_handler_config(?MODULE, NewHConfig2), 1325 Pid0 = whereis(h_proc_name()), 1326 MRef2 = erlang:monitor(process, Pid0), 1327 %% kill handler 1328 send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), 1329 receive 1330 {'DOWN', MRef2, _, _, _Reason2} -> 1331 file_delete(Log), 1332 {ok,Pid1} = wait_for_process_up(RestartAfter * 3), 1333 false = (Pid1 == Pid0), 1334 ok 1335 after 1336 5000 -> 1337 Info2 = logger_olp:info(h_proc_name()), 1338 ct:pal("Handler state = ~p", [Info2]), 1339 ct:fail("Handler not dead! It should not have survived this!") 1340 end, 1341 ok. 1342restart_after(cleanup, _Config) -> 1343 ok = stop_handler(?MODULE). 1344 1345%% send handler requests (sync, info, reset, change_config) 1346%% during high load to verify that sync, dropping and flushing is 1347%% handled correctly. 1348handler_requests_under_load() -> 1349 [{timetrap,{minutes,3}}]. 1350handler_requests_under_load(Config) -> 1351 {Log,HConfig,StdHConfig} = 1352 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1353 NewHConfig = 1354 HConfig#{config => StdHConfig#{sync_mode_qlen => 2, 1355 drop_mode_qlen => 1000, 1356 flush_qlen => 2000, 1357 burst_limit_enable => false}}, 1358 ok = logger:update_handler_config(?MODULE, NewHConfig), 1359 Pid = spawn_link( 1360 fun() -> send_requests(1,[{logger_std_h,filesync,[?MODULE],[]}, 1361 {logger_olp,info,[h_proc_name()],[]}, 1362 {logger_olp,reset,[h_proc_name()],[]}, 1363 {logger,update_handler_config, 1364 [?MODULE, config, 1365 #{overload_kill_enable => false}], 1366 []}]) 1367 end), 1368 Sent = send_burst({t,10000}, seq, {chars,79}, notice), 1369 Pid ! {self(),finish}, 1370 ReqResult = receive {Pid,Result} -> Result end, 1371 Logged = count_lines(Log), 1372 ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", 1373 [Sent,Logged]), 1374 FindError = fun(Res) -> 1375 [E || E <- Res, 1376 is_tuple(E) andalso (element(1,E) == error)] 1377 end, 1378 Errors = [{Func,FindError(Res)} || {_,Func,_,Res} <- ReqResult], 1379 NoOfReqs = lists:foldl(fun({_,_,_,Res}, N) -> N + length(Res) end, 1380 0, ReqResult), 1381 ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]), 1382 ok = file_delete(Log). 1383handler_requests_under_load(cleanup, _Config) -> 1384 ok = stop_handler(?MODULE). 1385 1386recreate_deleted_log(Config) -> 1387 {Log,_HConfig,_StdHConfig} = 1388 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1389 logger:notice("first",?domain), 1390 logger_std_h:filesync(?MODULE), 1391 ok = file:rename(Log,Log++".old"), 1392 logger:notice("second",?domain), 1393 logger_std_h:filesync(?MODULE), 1394 {ok,<<"first\n">>} = file:read_file(Log++".old"), 1395 {ok,<<"second\n">>} = file:read_file(Log), 1396 ok. 1397recreate_deleted_log(cleanup, _Config) -> 1398 ok = stop_handler(?MODULE). 1399 1400reopen_changed_log(Config) -> 1401 {Log,_HConfig,_StdHConfig} = 1402 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1403 logger:notice("first",?domain), 1404 logger_std_h:filesync(?MODULE), 1405 ok = file:rename(Log,Log++".old"), 1406 ok = file:write_file(Log,""), 1407 logger:notice("second",?domain), 1408 logger_std_h:filesync(?MODULE), 1409 {ok,<<"first\n">>} = file:read_file(Log++".old"), 1410 {ok,<<"second\n">>} = file:read_file(Log), 1411 ok. 1412reopen_changed_log(cleanup, _Config) -> 1413 ok = stop_handler(?MODULE). 1414 1415rotate_size(Config) -> 1416 {Log,_HConfig,_StdHConfig} = 1417 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1418 ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, 1419 max_no_files=>2}}), 1420 1421 Str = lists:duplicate(19,$a), 1422 [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], 1423 logger_std_h:filesync(?MODULE), 1424 {ok,#file_info{size=1000}} = file:read_file_info(Log), 1425 {error,enoent} = file:read_file_info(Log++".0"), 1426 1427 logger:notice(Str,?domain), 1428 logger_std_h:filesync(?MODULE), 1429 {ok,#file_info{size=0}} = file:read_file_info(Log), 1430 {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), 1431 {error,enoent} = file:read_file_info(Log++".1"), 1432 1433 [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], 1434 logger_std_h:filesync(?MODULE), 1435 {ok,#file_info{size=0}} = file:read_file_info(Log), 1436 {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), 1437 {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), 1438 {error,enoent} = file:read_file_info(Log++".2"), 1439 1440 [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], 1441 logger_std_h:filesync(?MODULE), 1442 {ok,#file_info{size=1000}} = file:read_file_info(Log), 1443 {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), 1444 {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), 1445 {error,enoent} = file:read_file_info(Log++".2"), 1446 1447 logger:notice("bbbb",?domain), 1448 logger_std_h:filesync(?MODULE), 1449 {ok,#file_info{size=0}} = file:read_file_info(Log), 1450 {ok,#file_info{size=1005}} = file:read_file_info(Log++".0"), 1451 {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), 1452 {error,enoent} = file:read_file_info(Log++".2"), 1453 1454 ok. 1455rotate_size(cleanup,_Config) -> 1456 ok = stop_handler(?MODULE). 1457 1458rotate_size_compressed(Config) -> 1459 {Log,_HConfig,_StdHConfig} = 1460 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1461 ok = logger:update_handler_config(?MODULE, 1462 #{config=>#{max_no_bytes=>1000, 1463 max_no_files=>2, 1464 compress_on_rotate=>true}}), 1465 Str = lists:duplicate(19,$a), 1466 [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], 1467 logger_std_h:filesync(?MODULE), 1468 {ok,#file_info{size=1000}} = file:read_file_info(Log), 1469 {error,enoent} = file:read_file_info(Log++".0"), 1470 {error,enoent} = file:read_file_info(Log++".0.gz"), 1471 1472 logger:notice(Str,?domain), 1473 logger_std_h:filesync(?MODULE), 1474 {ok,#file_info{size=0}} = file:read_file_info(Log), 1475 {error,enoent} = file:read_file_info(Log++".0"), 1476 {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), 1477 {error,enoent} = file:read_file_info(Log++".1"), 1478 {error,enoent} = file:read_file_info(Log++".1.gz"), 1479 1480 [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], 1481 logger_std_h:filesync(?MODULE), 1482 {ok,#file_info{size=0}} = file:read_file_info(Log), 1483 {error,enoent} = file:read_file_info(Log++".0"), 1484 {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), 1485 {error,enoent} = file:read_file_info(Log++".1"), 1486 {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), 1487 {error,enoent} = file:read_file_info(Log++".2"), 1488 {error,enoent} = file:read_file_info(Log++".2.gz"), 1489 1490 [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], 1491 logger_std_h:filesync(?MODULE), 1492 {ok,#file_info{size=1000}} = file:read_file_info(Log), 1493 {error,enoent} = file:read_file_info(Log++".0"), 1494 {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), 1495 {error,enoent} = file:read_file_info(Log++".1"), 1496 {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), 1497 {error,enoent} = file:read_file_info(Log++".2"), 1498 {error,enoent} = file:read_file_info(Log++".2.gz"), 1499 1500 logger:notice("bbbb",?domain), 1501 logger_std_h:filesync(?MODULE), 1502 {ok,#file_info{size=0}} = file:read_file_info(Log), 1503 {error,enoent} = file:read_file_info(Log++".0"), 1504 {ok,#file_info{size=38}} = file:read_file_info(Log++".0.gz"), 1505 {error,enoent} = file:read_file_info(Log++".1"), 1506 {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), 1507 {error,enoent} = file:read_file_info(Log++".2"), 1508 {error,enoent} = file:read_file_info(Log++".2.gz"), 1509 1510 ok. 1511rotate_size_compressed(cleanup,_Config) -> 1512 ok = stop_handler(?MODULE). 1513 1514rotate_size_reopen(Config) -> 1515 {Log,_HConfig,_StdHConfig} = 1516 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1517 ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, 1518 max_no_files=>2}}), 1519 1520 Str = lists:duplicate(19,$a), 1521 [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], 1522 logger_std_h:filesync(?MODULE), 1523 {ok,#file_info{size=800}} = file:read_file_info(Log), 1524 1525 {ok,HConfig} = logger:get_handler_config(?MODULE), 1526 ok = logger:remove_handler(?MODULE), 1527 ok = logger:add_handler(?MODULE,maps:get(module,HConfig),HConfig), 1528 {ok,#file_info{size=800}} = file:read_file_info(Log), 1529 1530 [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], 1531 logger_std_h:filesync(?MODULE), 1532 {ok,#file_info{size=580}} = file:read_file_info(Log), 1533 {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), 1534 ok. 1535rotate_size_reopen(cleanup,_Config) -> 1536 ok = stop_handler(?MODULE). 1537 1538%% Test that it is possible to start the handler when there 1539%% exists a large file that needs rotating at startup. 1540rotate_on_start_compressed() -> 1541 [{timetrap,{minutes,5}}]. 1542rotate_on_start_compressed(Config) -> 1543 1544 application:ensure_all_started(os_mon), 1545 1546 case file_SUITE:disc_free(?config(priv_dir, Config)) of 1547 N when N >= 5 * (1 bsl 30), is_integer(N) -> 1548 ct:pal("Free disk: ~w KByte~n", [N]), 1549 Log = get_handler_log_name(rotate_on_start_compressed, Config), 1550 1551 %% Write a 1 GB file to disk 1552 {ok, D} = file:open(Log,[write]), 1553 [file:write(D,<<0:(1024*1024*8)>>) || _I <- lists:seq(1,1024)], 1554 file:close(D), 1555 1556 NumOfReqs = 500, 1557 1558 %% Start the handler that will compress and rotate the existing file 1559 ok = logger:add_handler(?MODULE, 1560 logger_std_h, 1561 #{config => #{sync_mode_qlen => 2, 1562 drop_mode_qlen => NumOfReqs+1, 1563 flush_qlen => 2*NumOfReqs, 1564 burst_limit_enable => false, 1565 max_no_bytes=>1048576, 1566 max_no_files=>10, 1567 compress_on_rotate=>true, 1568 type => {file,Log}}, 1569 filter_default=>stop, 1570 filters=>filter_only_this_domain(?MODULE), 1571 formatter=>{?MODULE,op}}), 1572 1573 %% Wait for compression to start 1574 timer:sleep(50), 1575 1576 %% We send a burst here in order to make sure that the 1577 %% compression has time to take place. The burst will 1578 %% trigger sync mode which means that there will be 1579 %% calls made to the file controller process which 1580 %% in turn means that when the burst is done the 1581 %% compression is done. 1582 send_burst({n,NumOfReqs}, seq, {chars,79}, notice), 1583 Lines = count_lines(Log), 1584 NumOfReqs = Lines, 1585 {ok,#file_info{size=1043656}} = file:read_file_info(Log++".0.gz"), 1586 ok; 1587 _ -> 1588 {skip,"Disk not large enough"} 1589 end. 1590rotate_on_start_compressed(cleanup,Config) -> 1591 application:stop(os_mon), 1592 application:stop(sasl), 1593 file:delete(get_handler_log_name(rotate_on_start_compressed, Config)), 1594 file:delete(get_handler_log_name(rotate_on_start_compressed, Config)++".0.gz"), 1595 ok = stop_handler(?MODULE). 1596 1597rotation_opts(Config) -> 1598 {Log,_HConfig,StdHConfig} = 1599 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1600 #{max_no_bytes:=infinity, 1601 max_no_files:=0, 1602 compress_on_rotate:=false} = StdHConfig, 1603 1604 %% Test bad rotation config 1605 {error,{invalid_config,_,_}} = 1606 logger:update_handler_config(?MODULE,config,#{max_no_bytes=>0}), 1607 {error,{invalid_config,_,_}} = 1608 logger:update_handler_config(?MODULE,config,#{max_no_files=>infinity}), 1609 {error,{invalid_config,_,_}} = 1610 logger:update_handler_config(?MODULE,config, 1611 #{compress_on_rotate=>undefined}), 1612 1613 1614 %% Test good rotation config - start with no rotation 1615 Str = lists:duplicate(19,$a), 1616 [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], 1617 logger_std_h:filesync(?MODULE), 1618 {ok,#file_info{size=200}} = file:read_file_info(Log), 1619 [] = filelib:wildcard(Log++".*"), 1620 1621 %% Turn on rotation, check that existing file is rotated since its 1622 %% size exceeds max_no_bytes 1623 ok = logger:update_handler_config(?MODULE, 1624 config, 1625 #{max_no_bytes=>100, 1626 max_no_files=>2}), 1627 timer:sleep(100), % give some time to execute config_changed 1628 {ok,#file_info{size=0}} = file:read_file_info(Log), 1629 Log0 = Log++".0", 1630 {ok,#file_info{size=200}} = file:read_file_info(Log0), 1631 [Log0] = filelib:wildcard(Log++".*"), 1632 1633 %% Fill all logs 1634 [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], 1635 logger_std_h:filesync(?MODULE), 1636 {ok,#file_info{size=20}} = file:read_file_info(Log), 1637 {ok,#file_info{size=120}} = file:read_file_info(Log0), 1638 {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), 1639 [_,_] = filelib:wildcard(Log++".*"), 1640 1641 %% Extend size and count and check that nothing changes with existing files 1642 ok = logger:update_handler_config(?MODULE, 1643 config, 1644 #{max_no_bytes=>200, 1645 max_no_files=>3}), 1646 timer:sleep(100), % give some time to execute config_changed 1647 {ok,#file_info{size=20}} = file:read_file_info(Log), 1648 {ok,#file_info{size=120}} = file:read_file_info(Log0), 1649 {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), 1650 [_,_] = filelib:wildcard(Log++".*"), 1651 1652 %% Add more log events and see that extended size and count works 1653 [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], 1654 logger_std_h:filesync(?MODULE), 1655 {ok,#file_info{size=0}} = file:read_file_info(Log), 1656 {ok,#file_info{size=220}} = file:read_file_info(Log0), 1657 {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), 1658 {ok,#file_info{size=120}} = file:read_file_info(Log++".2"), 1659 [_,_,_] = filelib:wildcard(Log++".*"), 1660 1661 %% Reduce count and check that archive files that exceed the new 1662 %% count are moved 1663 ok = logger:update_handler_config(?MODULE, 1664 config, 1665 #{max_no_files=>1}), 1666 timer:sleep(100), % give some time to execute config_changed 1667 {ok,#file_info{size=0}} = file:read_file_info(Log), 1668 {ok,#file_info{size=220}} = file:read_file_info(Log0), 1669 [Log0] = filelib:wildcard(Log++".*"), 1670 1671 %% Extend size and count again, and turn on compression. Check 1672 %% that archives are compressed 1673 ok = logger:update_handler_config(?MODULE, 1674 config, 1675 #{max_no_bytes=>100, 1676 max_no_files=>2, 1677 compress_on_rotate=>true}), 1678 timer:sleep(100), % give some time to execute config_changed 1679 {ok,#file_info{size=0}} = file:read_file_info(Log), 1680 Log0gz = Log0++".gz", 1681 {ok,#file_info{size=29}} = file:read_file_info(Log0gz), 1682 [Log0gz] = filelib:wildcard(Log++".*"), 1683 1684 %% Fill all logs 1685 [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], 1686 logger_std_h:filesync(?MODULE), 1687 {ok,#file_info{size=20}} = file:read_file_info(Log), 1688 {ok,#file_info{size=29}} = file:read_file_info(Log0gz), 1689 {ok,#file_info{size=29}} = file:read_file_info(Log++".1.gz"), 1690 [_,_] = filelib:wildcard(Log++".*"), 1691 1692 %% Reduce count and turn off compression. Check that archives that 1693 %% exceeds the new count are removed, and the rest are 1694 %% uncompressed. 1695 ok = logger:update_handler_config(?MODULE, 1696 config, 1697 #{max_no_files=>1, 1698 compress_on_rotate=>false}), 1699 timer:sleep(100), % give some time to execute config_changed 1700 {ok,#file_info{size=20}} = file:read_file_info(Log), 1701 {ok,#file_info{size=120}} = file:read_file_info(Log0), 1702 [Log0] = filelib:wildcard(Log++".*"), 1703 1704 %% Check that config and handler state agree on the current rotation settings 1705 {ok,#{config:=#{max_no_bytes:=100, 1706 max_no_files:=1, 1707 compress_on_rotate:=false}}} = 1708 logger:get_handler_config(?MODULE), 1709 #{cb_state:=#{handler_state:=#{max_no_bytes:=100, 1710 max_no_files:=1, 1711 compress_on_rotate:=false}}} = 1712 logger_olp:info(h_proc_name()), 1713 ok. 1714rotation_opts(cleanup,_Config) -> 1715 ok = stop_handler(?MODULE). 1716 1717rotation_opts_restart_handler(Config) -> 1718 {Log,_HConfig,_StdHConfig} = 1719 start_handler(?MODULE, ?FUNCTION_NAME, Config), 1720 ok = logger:update_handler_config(?MODULE, 1721 config, 1722 #{max_no_bytes=>100, 1723 max_no_files=>2}), 1724 1725 %% Fill all logs 1726 Str = lists:duplicate(19,$a), 1727 [logger:notice(Str,?domain) || _ <- lists:seq(1,15)], 1728 logger_std_h:filesync(?MODULE), 1729 {ok,#file_info{size=60}} = file:read_file_info(Log), 1730 {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), 1731 {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), 1732 [_,_] = filelib:wildcard(Log++".*"), 1733 1734 %% Stop/start handler and turn off rotation. Check that archives are removed. 1735 {ok,#{config:=StdHConfig1}=HConfig1} = logger:get_handler_config(?MODULE), 1736 ok = logger:remove_handler(?MODULE), 1737 ok = logger:add_handler( 1738 ?MODULE,logger_std_h, 1739 HConfig1#{config=>StdHConfig1#{max_no_bytes=>infinity}}), 1740 timer:sleep(100), 1741 {ok,#file_info{size=60}} = file:read_file_info(Log), 1742 [] = filelib:wildcard(Log++".*"), 1743 1744 %% Add some log events and check that file is no longer rotated. 1745 [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], 1746 logger_std_h:filesync(?MODULE), 1747 {ok,#file_info{size=260}} = file:read_file_info(Log), 1748 [] = filelib:wildcard(Log++".*"), 1749 1750 %% Stop/start handler and trun on rotation. Check that file is rotated. 1751 {ok,#{config:=StdHConfig2}=HConfig2} = logger:get_handler_config(?MODULE), 1752 ok = logger:remove_handler(?MODULE), 1753 ok = logger:add_handler( 1754 ?MODULE,logger_std_h, 1755 HConfig2#{config=>StdHConfig2#{max_no_bytes=>100, 1756 max_no_files=>2}}), 1757 timer:sleep(100), 1758 {ok,#file_info{size=0}} = file:read_file_info(Log), 1759 {ok,#file_info{size=260}} = file:read_file_info(Log++".0"), 1760 [_] = filelib:wildcard(Log++".*"), 1761 1762 %% Fill all logs 1763 [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], 1764 logger_std_h:filesync(?MODULE), 1765 {ok,#file_info{size=80}} = file:read_file_info(Log), 1766 {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), 1767 {ok,#file_info{size=260}} = file:read_file_info(Log++".1"), 1768 1769 %% Stop/start handler, reduce count and turn on compression. Check 1770 %% that excess archives are removed, and the rest compressed. 1771 {ok,#{config:=StdHConfig3}=HConfig3} = logger:get_handler_config(?MODULE), 1772 ok = logger:remove_handler(?MODULE), 1773 ok = logger:add_handler( 1774 ?MODULE,logger_std_h, 1775 HConfig3#{config=>StdHConfig3#{max_no_bytes=>75, 1776 max_no_files=>1, 1777 compress_on_rotate=>true}}), 1778 timer:sleep(500), 1779 {ok,#file_info{size=0}} = file:read_file_info(Log), 1780 {ok,#file_info{size=29}} = file:read_file_info(Log++".0.gz"), 1781 [_] = filelib:wildcard(Log++".*"), 1782 1783 %% Stop/start handler and turn off compression. Check that achives 1784 %% are decompressed. 1785 {ok,#{config:=StdHConfig4}=HConfig4} = logger:get_handler_config(?MODULE), 1786 ok = logger:remove_handler(?MODULE), 1787 ok = logger:add_handler( 1788 ?MODULE,logger_std_h, 1789 HConfig4#{config=>StdHConfig4#{compress_on_rotate=>false}}), 1790 timer:sleep(100), 1791 {ok,#file_info{size=0}} = file:read_file_info(Log), 1792 {ok,#file_info{size=80}} = file:read_file_info(Log++".0"), 1793 [_] = filelib:wildcard(Log++".*"), 1794 1795 ok. 1796rotation_opts_restart_handler(cleanup,_Config) -> 1797 ok = stop_handler(?MODULE). 1798 1799%%%----------------------------------------------------------------- 1800%%% 1801send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> 1802 receive 1803 {From,finish} -> 1804 From ! {self(),Reqs} 1805 after 1806 TO -> 1807 Result = apply(Mod,Func,Args), 1808 send_requests(TO, Rs ++ [{Mod,Func,Args,[Result|Res]}]) 1809 end. 1810 1811 1812%%%----------------------------------------------------------------- 1813%%% 1814start_handler(Name, TTY, _Config) when TTY == standard_io; 1815 TTY == standard_error-> 1816 ok = logger:add_handler(Name, 1817 logger_std_h, 1818 #{config => #{type => TTY}, 1819 filter_default=>stop, 1820 filters=>filter_only_this_domain(Name), 1821 formatter=>{?MODULE,op}}), 1822 {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), 1823 {HConfig,StdHConfig}; 1824 1825start_handler(Name, FuncName, Config) -> 1826 Log = get_handler_log_name(FuncName, Config), 1827 ct:pal("Logging to ~tp", [Log]), 1828 Type = {file,Log}, 1829 _ = file_delete(Log), 1830 ok = logger:add_handler(Name, 1831 logger_std_h, 1832 #{config => #{type => Type}, 1833 filter_default=>stop, 1834 filters=>filter_only_this_domain(Name), 1835 formatter=>{?MODULE,op}}), 1836 {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), 1837 {Log,HConfig,StdHConfig}. 1838 1839get_handler_log_name(FuncName, Config) -> 1840 Dir = ?config(priv_dir,Config), 1841 filename:join(Dir, lists:concat([FuncName,".log"])). 1842 1843filter_only_this_domain(Name) -> 1844 [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, 1845 {domain,{fun logger_filters:domain/2,{log,super,[Name]}}}]. 1846 1847stop_handler(Name) -> 1848 R = logger:remove_handler(Name), 1849 ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), 1850 R. 1851 1852count_lines(File) -> 1853 wait_until_written(File, -1), 1854 count_lines1(File). 1855 1856wait_until_written(File, Sz) -> 1857 timer:sleep(2000), 1858 case file:read_file_info(File) of 1859 {error,enoent} when Sz == -1 -> 1860 wait_until_written(File, Sz); 1861 {ok,#file_info{size = Sz}} -> 1862 timer:sleep(1000), 1863 case file:read_file_info(File) of 1864 {ok,#file_info{size = Sz}} -> 1865 ok; 1866 {ok,#file_info{size = Sz1}} -> 1867 wait_until_written(File, Sz1) 1868 end; 1869 {ok,#file_info{size = Sz1}} -> 1870 wait_until_written(File, Sz1) 1871 end. 1872 1873count_lines1(File) -> 1874 {_,Dev} = file:open(File, [read]), 1875 Lines = count_lines2(Dev, 0), 1876 file:close(Dev), 1877 Lines. 1878 1879count_lines2(Dev, LC) -> 1880 case file:read_line(Dev) of 1881 {ok,"Handler logger_std_h_SUITE " ++_} -> 1882 %% Not counting handler info 1883 count_lines2(Dev,LC); 1884 {ok,_} -> 1885 count_lines2(Dev,LC+1); 1886 eof -> LC 1887 end. 1888 1889send_burst(NorT, Type, {chars,Sz}, Class) -> 1890 Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], 1891 case NorT of 1892 {n,N} -> 1893 %% process_flag(priority, high), 1894 send_n_burst(N, Type, Text, Class), 1895 %% process_flag(priority, normal), 1896 N; 1897 {t,T} -> 1898 ct:pal("Sending messages sequentially for ~w ms", [T]), 1899 T0 = erlang:monotonic_time(millisecond), 1900 send_t_burst(T0, T, Text, Class, 0) 1901 end. 1902 1903send_n_burst(0, _, _Text, _Class) -> 1904 ok; 1905send_n_burst(N, seq, Text, Class) -> 1906 ok = logger:Class(Text, ?domain), 1907 send_n_burst(N-1, seq, Text, Class); 1908send_n_burst(N, {spawn,Ps,TO}, Text, Class) -> 1909 ct:pal("~w processes each sending ~w messages", [Ps,N]), 1910 MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, 1911 monitor(process,spawn_link(per_proc_fun(N,Text,Class,X))) 1912 end || X <- lists:seq(1,Ps)], 1913 lists:foreach(fun(MRef) -> 1914 receive 1915 {'DOWN', MRef, _, _, _} -> 1916 ok 1917 end 1918 end, MRefs), 1919 ct:pal("Message burst sent", []), 1920 ok. 1921 1922send_t_burst(T0, T, Text, Class, N) -> 1923 T1 = erlang:monotonic_time(millisecond), 1924 if (T1-T0) > T -> 1925 N; 1926 true -> 1927 ok = logger:Class(Text, ?domain), 1928 send_t_burst(T0, T, Text, Class, N+1) 1929 end. 1930 1931per_proc_fun(N,Text,Class,X) when X rem 2 == 0 -> 1932 fun() -> 1933 process_flag(priority,high), 1934 send_n_burst(N, seq, Text, Class) 1935 end; 1936per_proc_fun(N,Text,Class,_) -> 1937 fun() -> 1938 send_n_burst(N, seq, Text, Class) 1939 end. 1940 1941%%%----------------------------------------------------------------- 1942%%% Formatter callback 1943%%% Using this to send the formatted string back to the test case 1944%%% process - so it can check for logged events. 1945format(_,bad_return) -> 1946 bad_return; 1947format(_,crash) -> 1948 erlang:error(formatter_crashed); 1949format(#{msg:={string,String0}},no_nl) -> 1950 String = unicode:characters_to_list(String0), 1951 String; 1952format(#{msg:={string,String0}},nl) -> 1953 String = unicode:characters_to_list(String0), 1954 String++"\n"; 1955format(#{msg:={string,String0}},op) -> 1956 String = unicode:characters_to_list(String0), 1957 String++"\n"; 1958format(#{msg:={report,#{label:={supervisor,progress}}}},op) -> 1959 ""; 1960format(#{msg:={report,#{label:={gen_server,terminate}}}},op) -> 1961 ""; 1962format(#{msg:={report,#{label:={proc_lib,crash}}}},op) -> 1963 ""; 1964format(#{msg:={F,A}},OpOrPid) when is_list(F), is_list(A) -> 1965 String = lists:flatten(io_lib:format(F,A)), 1966 if is_pid(OpOrPid) -> OpOrPid ! {log,String}; 1967 true -> ok 1968 end, 1969 String++"\n"; 1970format(#{msg:={string,String0}},Pid) -> 1971 String = unicode:characters_to_list(String0), 1972 Pid ! {log,String}, 1973 String++"\n". 1974 1975add_remove_instance_nofile(Type) -> 1976 ok = logger:add_handler(?MODULE,logger_std_h, 1977 #{config => #{type => Type}, 1978 filter_default=>stop, 1979 filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), 1980 formatter=>{?MODULE,self()}}), 1981 Pid = whereis(h_proc_name()), 1982 true = is_pid(Pid), 1983 group_leader(group_leader(),Pid), % to get printouts in test log 1984 logger:notice(M1=?msg,?domain), 1985 ?check(M1), 1986 %% check that sync doesn't do damage even if not relevant 1987 ok = logger_std_h:filesync(?MODULE), 1988 ok = logger:remove_handler(?MODULE), 1989 timer:sleep(500), 1990 undefined = whereis(h_proc_name()), 1991 logger:notice(?msg,?domain), 1992 ?check_no_log, 1993 ok. 1994 1995logger_std_h_remove() -> 1996 logger:remove_handler(?MODULE). 1997logger_std_h_remove(Id) -> 1998 logger:remove_handler(Id). 1999 2000try_read_file(FileName, Expected, Time) when Time > 0 -> 2001 case file:read_file(FileName) of 2002 Expected -> 2003 ok; 2004 Error = {error,_Reason} -> 2005 ct:pal("Can't read ~tp: ~tp", [FileName,Error]), 2006 erlang:error(Error); 2007 Got -> 2008 ct:pal("try_read_file got ~tp", [Got]), 2009 timer:sleep(500), 2010 try_read_file(FileName, Expected, Time-500) 2011 end; 2012try_read_file(FileName, Expected, _) -> 2013 ct:pal("Missing pattern ~tp in ~tp", [Expected,FileName]), 2014 erlang:error({error,missing_expected_pattern}). 2015 2016try_match_file(FileName, Pattern, Time) -> 2017 try_match_file(FileName, Pattern, Time, <<>>). 2018 2019try_match_file(FileName, Pattern, Time, _) when Time > 0 -> 2020 case file:read_file(FileName) of 2021 {ok, Bin} -> 2022 case re:run(Bin,Pattern,[{capture,none}]) of 2023 match -> 2024 unicode:characters_to_list(Bin); 2025 _ -> 2026 timer:sleep(100), 2027 try_match_file(FileName, Pattern, Time-100, Bin) 2028 end; 2029 Error -> 2030 erlang:error(Error) 2031 end; 2032try_match_file(_,Pattern,_,Incorrect) -> 2033 ct:pal("try_match_file did not match pattern: ~p~nGot: ~p~n", 2034 [Pattern,Incorrect]), 2035 erlang:error({error,not_matching_pattern,Pattern,Incorrect}). 2036 2037repeat_until_ok(Fun, N) -> 2038 repeat_until_ok(Fun, 0, N, undefined). 2039 2040repeat_until_ok(_Fun, Stop, Stop, Reason) -> 2041 {fails,Reason}; 2042 2043repeat_until_ok(Fun, C, Stop, FirstReason) -> 2044 if C > 0 -> timer:sleep(5000); 2045 true -> ok 2046 end, 2047 try Fun() of 2048 Result -> 2049 {ok,{C,Result}} 2050 catch 2051 _:Reason:Stack -> 2052 ct:pal("Test fails: ~p (~p)~n", [Reason,hd(Stack)]), 2053 if FirstReason == undefined -> 2054 repeat_until_ok(Fun, C+1, Stop, {Reason,Stack}); 2055 true -> 2056 repeat_until_ok(Fun, C+1, Stop, FirstReason) 2057 end 2058 end. 2059 2060 2061%%%----------------------------------------------------------------- 2062%%% 2063start_op_trace() -> 2064 TraceFun = fun({trace,_,call,{_Mod,Func,Details}}, Pid) -> 2065 Pid ! {trace_call,Func,Details}, 2066 Pid; 2067 ({trace,_,return_from,{_Mod,Func,_},RetVal}, Pid) -> 2068 Pid ! {trace_return,Func,RetVal}, 2069 Pid 2070 end, 2071 TRecvPid = spawn_link(fun() -> trace_receiver(5000) end), 2072 {ok,_} = dbg:tracer(process, {TraceFun, TRecvPid}), 2073 2074 {ok,_} = dbg:p(whereis(h_proc_name()), [c]), 2075 {ok,_} = dbg:p(self(), [c]), 2076 2077 MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), 2078 {ok,_} = dbg:tpl(logger_h_common, check_load, 1, MS1), 2079 2080 {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), 2081 2082 MS2 = dbg:fun2ms(fun([_,mode]) -> return_trace() end), 2083 {ok,_} = dbg:tpl(ets, lookup, 2, MS2), 2084 2085 ct:pal("Tracing started!", []), 2086 TRecvPid. 2087 2088stop_op_trace(TRecvPid) -> 2089 stop_clear(), 2090 unlink(TRecvPid), 2091 exit(TRecvPid, kill), 2092 ok. 2093 2094find_mode(flush, Events) -> 2095 lists:any(fun({trace_call,flush_log_requests,[_,_]}) -> true; 2096 (_) -> false 2097 end, Events); 2098find_mode(Mode, Events) -> 2099 lists:keymember([{mode,Mode}], 3, Events). 2100 2101%% find_switch(_From, To, Events) -> 2102%% try lists:foldl(fun({trace_return,check_load,{To,_,_,_}}, 2103%% {trace_call,check_load,[#{mode := From}]}) -> 2104%% throw(match); 2105%% (Event, _) -> 2106%% Event 2107%% end, undefined, Events) of 2108%% _ -> false 2109%% catch 2110%% throw:match -> true 2111%% end. 2112 2113analyse_trace(TRecvPid, TestFun) -> 2114 TRecvPid ! {test,self(),TestFun}, 2115 receive 2116 {result,TRecvPid,Result} -> 2117 Result 2118 after 2119 60000 -> 2120 fails 2121 end. 2122 2123trace_receiver(IdleT) -> 2124 Msgs = receive_until_idle(IdleT, 5, []), 2125 ct:pal("~w trace events generated", [length(Msgs)]), 2126 analyse(Msgs). 2127 2128receive_until_idle(IdleT, WaitN, Msgs) -> 2129 receive 2130 Msg = {trace_call,_,_} -> 2131 receive_until_idle(IdleT, 5, [Msg | Msgs]); 2132 Msg = {trace_return,_,_} -> 2133 receive_until_idle(IdleT, 5, [Msg | Msgs]) 2134 after 2135 IdleT -> 2136 if WaitN == 0 -> 2137 Msgs; 2138 true -> 2139 receive_until_idle(IdleT, WaitN-1, Msgs) 2140 end 2141 end. 2142 2143analyse(Msgs) -> 2144 receive 2145 {test,From,TestFun} -> 2146 From ! {result,self(),TestFun(Msgs)}, 2147 analyse(Msgs) 2148 end. 2149 2150start_tracer(Trace,Expected) -> 2151 Pid = self(), 2152 FileCtrlPid = maps:get(file_ctrl_pid, 2153 maps:get(handler_state, 2154 maps:get(cb_state, 2155 logger_olp:info(h_proc_name())))), 2156 {ok,_} = dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), 2157 dbg:p(whereis(h_proc_name()),[c]), 2158 dbg:p(FileCtrlPid,[c]), 2159 tpl(Trace), 2160 ok. 2161 2162tpl([{M,F,A}|Trace]) -> 2163 tpl([{{M,F,A},[]}|Trace]); 2164tpl([{{M,F,A},MS}|Trace]) -> 2165 {ok,Match} = dbg:tpl(M,F,A,MS), 2166 case lists:keyfind(matched,1,Match) of 2167 {_,_,1} -> 2168 ok; 2169 _ -> 2170 stop_clear(), 2171 throw({skip,"Can't trace "++atom_to_list(M)++":"++ 2172 atom_to_list(F)++"/"++integer_to_list(A)}) 2173 end, 2174 tpl(Trace); 2175tpl([]) -> 2176 ok. 2177 2178stop_clear() -> 2179 dbg:stop_clear(), 2180 %% Remove tracer from all processes in order to eliminate 2181 %% race conditions. 2182 erlang:trace(all,false,[all]). 2183 2184tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, 2185 {Pid,[{Mod,Func,Op}|Expected]}) -> 2186 maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); 2187tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[Data,_]}}, 2188 {Pid,[{Mod,Func,Data}|Expected]}) -> 2189 maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); 2190tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> 2191 maybe_tracer_done(Pid,Expected,{Mod,Func}); 2192tracer({trace,_,call,Call}, {Pid,Expected}) -> 2193 ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]), 2194 Pid ! {tracer_got_unexpected,Call,Expected}, 2195 {Pid,Expected}. 2196 2197maybe_tracer_done(Pid,[]=Expected,Got) -> 2198 ct:log("Tracer got: ~p~n",[Got]), 2199 Pid ! {tracer_done,0}, 2200 {Pid,Expected}; 2201maybe_tracer_done(Pid,[{no_more,T}]=Expected,Got) -> 2202 ct:log("Tracer got: ~p~n",[Got]), 2203 Pid ! {tracer_done,T}, 2204 {Pid,Expected}; 2205maybe_tracer_done(Pid,Expected,Got) -> 2206 ct:log("Tracer got: ~p~n",[Got]), 2207 {Pid,Expected}. 2208 2209check_tracer(T) -> 2210 check_tracer(T,fun() -> ct:fail({timeout,tracer}) end). 2211check_tracer(T,TimeoutFun) -> 2212 receive 2213 {tracer_done,Delay} -> 2214 %% Possibly wait Delay ms to check that no unexpected 2215 %% traces are received 2216 check_tracer(Delay,fun() -> ok end); 2217 {tracer_got_unexpected,Got,Expected} -> 2218 stop_clear(), 2219 ct:fail({tracer_got_unexpected,Got,Expected}) 2220 after T -> 2221 stop_clear(), 2222 TimeoutFun() 2223 end. 2224 2225escape([C|Rest]) -> 2226 %% The characters that have to be escaped in a regex 2227 case lists:member(C,"[-[\]{}()*+?.,\\^$|#\s]") of 2228 true -> 2229 [$\\,C|escape(Rest)]; 2230 false -> 2231 [C|escape(Rest)] 2232 end; 2233escape([]) -> 2234 []. 2235 2236h_proc_name() -> 2237 h_proc_name(?MODULE). 2238h_proc_name(Name) -> 2239 ?name_to_reg_name(logger_std_h,Name). 2240 2241wait_for_process_up(T) -> 2242 wait_for_process_up(?MODULE, h_proc_name(), T). 2243 2244wait_for_process_up(Name, RegName, T) -> 2245 N = (T div 500) + 1, 2246 wait_for_process_up1(Name, RegName, N). 2247 2248wait_for_process_up1(_Name, _RegName, 0) -> 2249 error; 2250wait_for_process_up1(Name, RegName, N) -> 2251 timer:sleep(500), 2252 case whereis(RegName) of 2253 Pid when is_pid(Pid) -> 2254 case logger:get_handler_config(Name) of 2255 {ok,_} -> 2256 %% ct:pal("Process ~p up (~p tries left)",[Name,N]), 2257 {ok,Pid}; 2258 _ -> 2259 wait_for_process_up1(Name, RegName, N-1) 2260 end; 2261 undefined -> 2262 %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]), 2263 wait_for_process_up1(Name, RegName, N-1) 2264 end. 2265 2266filesync_rep_int() -> 2267 case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of 2268 true -> 5500; 2269 false -> ?FILESYNC_REPEAT_INTERVAL + 500 2270 end. 2271 2272 2273file_delete(Log) -> 2274 file:delete(Log). 2275