diff options
78 files changed, 1489 insertions, 1529 deletions
diff --git a/OTP_VERSION b/OTP_VERSION index 0ecacc9d29..0dcb4b8807 100644 --- a/OTP_VERSION +++ b/OTP_VERSION @@ -1 +1 @@ -21.1.3 +21.1.4 diff --git a/bootstrap/bin/no_dot_erlang.boot b/bootstrap/bin/no_dot_erlang.boot Binary files differindex 127072b3ed..d3efecd3d9 100644 --- a/bootstrap/bin/no_dot_erlang.boot +++ b/bootstrap/bin/no_dot_erlang.boot diff --git a/bootstrap/bin/start.boot b/bootstrap/bin/start.boot Binary files differindex 127072b3ed..d3efecd3d9 100644 --- a/bootstrap/bin/start.boot +++ b/bootstrap/bin/start.boot diff --git a/bootstrap/bin/start_clean.boot b/bootstrap/bin/start_clean.boot Binary files differindex 127072b3ed..d3efecd3d9 100644 --- a/bootstrap/bin/start_clean.boot +++ b/bootstrap/bin/start_clean.boot diff --git a/bootstrap/lib/compiler/ebin/beam_asm.beam b/bootstrap/lib/compiler/ebin/beam_asm.beam Binary files differindex c0db0d1ac4..03eb4986e4 100644 --- a/bootstrap/lib/compiler/ebin/beam_asm.beam +++ b/bootstrap/lib/compiler/ebin/beam_asm.beam diff --git a/bootstrap/lib/compiler/ebin/beam_jump.beam b/bootstrap/lib/compiler/ebin/beam_jump.beam Binary files differindex 6af8a015c0..a77c5caf36 100644 --- a/bootstrap/lib/compiler/ebin/beam_jump.beam +++ b/bootstrap/lib/compiler/ebin/beam_jump.beam diff --git a/bootstrap/lib/compiler/ebin/beam_type.beam b/bootstrap/lib/compiler/ebin/beam_type.beam Binary files differindex 266c04acfd..fe2824b20e 100644 --- a/bootstrap/lib/compiler/ebin/beam_type.beam +++ b/bootstrap/lib/compiler/ebin/beam_type.beam diff --git a/bootstrap/lib/compiler/ebin/beam_utils.beam b/bootstrap/lib/compiler/ebin/beam_utils.beam Binary files differindex 5648719621..7c65d7b6e4 100644 --- a/bootstrap/lib/compiler/ebin/beam_utils.beam +++ b/bootstrap/lib/compiler/ebin/beam_utils.beam diff --git a/bootstrap/lib/compiler/ebin/beam_validator.beam b/bootstrap/lib/compiler/ebin/beam_validator.beam Binary files differindex 2bcec9ca3c..6d2c9eb69d 100644 --- a/bootstrap/lib/compiler/ebin/beam_validator.beam +++ b/bootstrap/lib/compiler/ebin/beam_validator.beam diff --git a/bootstrap/lib/compiler/ebin/compile.beam b/bootstrap/lib/compiler/ebin/compile.beam Binary files differindex d1a9058417..3f52b9463d 100644 --- a/bootstrap/lib/compiler/ebin/compile.beam +++ b/bootstrap/lib/compiler/ebin/compile.beam diff --git a/bootstrap/lib/compiler/ebin/compiler.app b/bootstrap/lib/compiler/ebin/compiler.app index 1506292674..f53cc32c12 100644 --- a/bootstrap/lib/compiler/ebin/compiler.app +++ b/bootstrap/lib/compiler/ebin/compiler.app @@ -19,7 +19,7 @@ {application, compiler, [{description, "ERTS CXC 138 10"}, - {vsn, "7.1.5"}, + {vsn, "7.2.7"}, {modules, [ beam_a, beam_asm, diff --git a/bootstrap/lib/compiler/ebin/sys_core_bsm.beam b/bootstrap/lib/compiler/ebin/sys_core_bsm.beam Binary files differindex d14579410c..0bc7588ab3 100644 --- a/bootstrap/lib/compiler/ebin/sys_core_bsm.beam +++ b/bootstrap/lib/compiler/ebin/sys_core_bsm.beam diff --git a/bootstrap/lib/compiler/ebin/sys_core_fold.beam b/bootstrap/lib/compiler/ebin/sys_core_fold.beam Binary files differindex 073bb041d4..9def7c8d2c 100644 --- a/bootstrap/lib/compiler/ebin/sys_core_fold.beam +++ b/bootstrap/lib/compiler/ebin/sys_core_fold.beam diff --git a/bootstrap/lib/compiler/ebin/v3_codegen.beam b/bootstrap/lib/compiler/ebin/v3_codegen.beam Binary files differindex c537f1e550..4700b80b93 100644 --- a/bootstrap/lib/compiler/ebin/v3_codegen.beam +++ b/bootstrap/lib/compiler/ebin/v3_codegen.beam diff --git a/bootstrap/lib/compiler/ebin/v3_core.beam b/bootstrap/lib/compiler/ebin/v3_core.beam Binary files differindex 162105c0bf..6a76fba69a 100644 --- a/bootstrap/lib/compiler/ebin/v3_core.beam +++ b/bootstrap/lib/compiler/ebin/v3_core.beam diff --git a/bootstrap/lib/kernel/ebin/error_logger.beam b/bootstrap/lib/kernel/ebin/error_logger.beam Binary files differindex 8dd3c07f71..08ec3e0e1a 100644 --- a/bootstrap/lib/kernel/ebin/error_logger.beam +++ b/bootstrap/lib/kernel/ebin/error_logger.beam diff --git a/bootstrap/lib/kernel/ebin/hipe_unified_loader.beam b/bootstrap/lib/kernel/ebin/hipe_unified_loader.beam Binary files differindex 989fceaa2c..7f205de75f 100644 --- a/bootstrap/lib/kernel/ebin/hipe_unified_loader.beam +++ b/bootstrap/lib/kernel/ebin/hipe_unified_loader.beam diff --git a/bootstrap/lib/kernel/ebin/inet.beam b/bootstrap/lib/kernel/ebin/inet.beam Binary files differindex 7df45ea492..cece8e6e85 100644 --- a/bootstrap/lib/kernel/ebin/inet.beam +++ b/bootstrap/lib/kernel/ebin/inet.beam diff --git a/bootstrap/lib/kernel/ebin/inet6_tcp.beam b/bootstrap/lib/kernel/ebin/inet6_tcp.beam Binary files differindex db0ead9cdd..b2dc48d794 100644 --- a/bootstrap/lib/kernel/ebin/inet6_tcp.beam +++ b/bootstrap/lib/kernel/ebin/inet6_tcp.beam diff --git a/bootstrap/lib/kernel/ebin/inet_tcp.beam b/bootstrap/lib/kernel/ebin/inet_tcp.beam Binary files differindex 304272a20d..5e3d9b307b 100644 --- a/bootstrap/lib/kernel/ebin/inet_tcp.beam +++ b/bootstrap/lib/kernel/ebin/inet_tcp.beam diff --git a/bootstrap/lib/kernel/ebin/inet_tcp_dist.beam b/bootstrap/lib/kernel/ebin/inet_tcp_dist.beam Binary files differindex c33a9e7f3a..fdfe042445 100644 --- a/bootstrap/lib/kernel/ebin/inet_tcp_dist.beam +++ b/bootstrap/lib/kernel/ebin/inet_tcp_dist.beam diff --git a/bootstrap/lib/kernel/ebin/kernel.app b/bootstrap/lib/kernel/ebin/kernel.app index 340ed8653f..898ed0a048 100644 --- a/bootstrap/lib/kernel/ebin/kernel.app +++ b/bootstrap/lib/kernel/ebin/kernel.app @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -22,7 +22,7 @@ {application, kernel, [ {description, "ERTS CXC 138 10"}, - {vsn, "5.4.3"}, + {vsn, "6.1"}, {modules, [application, application_controller, application_master, @@ -67,6 +67,7 @@ logger_filters, logger_formatter, logger_h_common, + logger_handler_watcher, logger_server, logger_simple_h, logger_std_h, @@ -129,6 +130,7 @@ kernel_refc, kernel_sup, logger, + logger_handler_watcher, logger_sup, net_kernel, net_sup, @@ -144,6 +146,6 @@ {logger_sasl_compatible, false} ]}, {mod, {kernel, []}}, - {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} + {runtime_dependencies, ["erts-10.1", "stdlib-3.5", "sasl-3.0"]} ] }. diff --git a/bootstrap/lib/kernel/ebin/logger.beam b/bootstrap/lib/kernel/ebin/logger.beam Binary files differindex e6d8f5b2c6..26e0d3b0f1 100644 --- a/bootstrap/lib/kernel/ebin/logger.beam +++ b/bootstrap/lib/kernel/ebin/logger.beam diff --git a/bootstrap/lib/kernel/ebin/logger_backend.beam b/bootstrap/lib/kernel/ebin/logger_backend.beam Binary files differindex be448bd75c..b2e7854689 100644 --- a/bootstrap/lib/kernel/ebin/logger_backend.beam +++ b/bootstrap/lib/kernel/ebin/logger_backend.beam diff --git a/bootstrap/lib/kernel/ebin/logger_config.beam b/bootstrap/lib/kernel/ebin/logger_config.beam Binary files differindex 52f7847561..2d1d9f9919 100644 --- a/bootstrap/lib/kernel/ebin/logger_config.beam +++ b/bootstrap/lib/kernel/ebin/logger_config.beam diff --git a/bootstrap/lib/kernel/ebin/logger_disk_log_h.beam b/bootstrap/lib/kernel/ebin/logger_disk_log_h.beam Binary files differindex cc1b649eb7..094ca34dc4 100644 --- a/bootstrap/lib/kernel/ebin/logger_disk_log_h.beam +++ b/bootstrap/lib/kernel/ebin/logger_disk_log_h.beam diff --git a/bootstrap/lib/kernel/ebin/logger_formatter.beam b/bootstrap/lib/kernel/ebin/logger_formatter.beam Binary files differindex 7f7d77ab28..3e99f7e1fa 100644 --- a/bootstrap/lib/kernel/ebin/logger_formatter.beam +++ b/bootstrap/lib/kernel/ebin/logger_formatter.beam diff --git a/bootstrap/lib/kernel/ebin/logger_h_common.beam b/bootstrap/lib/kernel/ebin/logger_h_common.beam Binary files differindex 7d96f2d69e..e232c87059 100644 --- a/bootstrap/lib/kernel/ebin/logger_h_common.beam +++ b/bootstrap/lib/kernel/ebin/logger_h_common.beam diff --git a/bootstrap/lib/kernel/ebin/logger_handler_watcher.beam b/bootstrap/lib/kernel/ebin/logger_handler_watcher.beam Binary files differnew file mode 100644 index 0000000000..44bc104ff9 --- /dev/null +++ b/bootstrap/lib/kernel/ebin/logger_handler_watcher.beam diff --git a/bootstrap/lib/kernel/ebin/logger_server.beam b/bootstrap/lib/kernel/ebin/logger_server.beam Binary files differindex 4885c0992a..c7c9b11962 100644 --- a/bootstrap/lib/kernel/ebin/logger_server.beam +++ b/bootstrap/lib/kernel/ebin/logger_server.beam diff --git a/bootstrap/lib/kernel/ebin/logger_std_h.beam b/bootstrap/lib/kernel/ebin/logger_std_h.beam Binary files differindex e8c3bb83d0..aa4bd9b218 100644 --- a/bootstrap/lib/kernel/ebin/logger_std_h.beam +++ b/bootstrap/lib/kernel/ebin/logger_std_h.beam diff --git a/bootstrap/lib/kernel/ebin/logger_sup.beam b/bootstrap/lib/kernel/ebin/logger_sup.beam Binary files differindex 9bef3c861c..32eb526a09 100644 --- a/bootstrap/lib/kernel/ebin/logger_sup.beam +++ b/bootstrap/lib/kernel/ebin/logger_sup.beam diff --git a/bootstrap/lib/kernel/ebin/net_kernel.beam b/bootstrap/lib/kernel/ebin/net_kernel.beam Binary files differindex 0a565d542d..a62690e27a 100644 --- a/bootstrap/lib/kernel/ebin/net_kernel.beam +++ b/bootstrap/lib/kernel/ebin/net_kernel.beam diff --git a/bootstrap/lib/kernel/include/dist.hrl b/bootstrap/lib/kernel/include/dist.hrl index 6baaa35d72..003852f1b0 100644 --- a/bootstrap/lib/kernel/include/dist.hrl +++ b/bootstrap/lib/kernel/include/dist.hrl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1999-2016. All Rights Reserved. +%% Copyright Ericsson AB 1999-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. diff --git a/bootstrap/lib/kernel/include/dist_util.hrl b/bootstrap/lib/kernel/include/dist_util.hrl index eeb0f8dd43..56f775f060 100644 --- a/bootstrap/lib/kernel/include/dist_util.hrl +++ b/bootstrap/lib/kernel/include/dist_util.hrl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1999-2016. All Rights Reserved. +%% Copyright Ericsson AB 1999-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. diff --git a/bootstrap/lib/kernel/include/logger.hrl b/bootstrap/lib/kernel/include/logger.hrl index 2143ccd297..b09977e0f2 100644 --- a/bootstrap/lib/kernel/include/logger.hrl +++ b/bootstrap/lib/kernel/include/logger.hrl @@ -32,6 +32,10 @@ -define(LOG_DEBUG(A,B),?DO_LOG(debug,[A,B])). -define(LOG_DEBUG(A,B,C),?DO_LOG(debug,[A,B,C])). +-define(LOG(L,A),?DO_LOG(L,[A])). +-define(LOG(L,A,B),?DO_LOG(L,[A,B])). +-define(LOG(L,A,B,C),?DO_LOG(L,[A,B,C])). + -define(LOCATION,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY}, line=>?LINE, file=>?FILE}). diff --git a/bootstrap/lib/stdlib/ebin/beam_lib.beam b/bootstrap/lib/stdlib/ebin/beam_lib.beam Binary files differindex b17a9b1947..ee20aced6b 100644 --- a/bootstrap/lib/stdlib/ebin/beam_lib.beam +++ b/bootstrap/lib/stdlib/ebin/beam_lib.beam diff --git a/bootstrap/lib/stdlib/ebin/dets.beam b/bootstrap/lib/stdlib/ebin/dets.beam Binary files differindex 05b575cd05..a7500207db 100644 --- a/bootstrap/lib/stdlib/ebin/dets.beam +++ b/bootstrap/lib/stdlib/ebin/dets.beam diff --git a/bootstrap/lib/stdlib/ebin/epp.beam b/bootstrap/lib/stdlib/ebin/epp.beam Binary files differindex c87665ff86..dba73e824b 100644 --- a/bootstrap/lib/stdlib/ebin/epp.beam +++ b/bootstrap/lib/stdlib/ebin/epp.beam diff --git a/bootstrap/lib/stdlib/ebin/erl_eval.beam b/bootstrap/lib/stdlib/ebin/erl_eval.beam Binary files differindex eea70718c8..4d96a82267 100644 --- a/bootstrap/lib/stdlib/ebin/erl_eval.beam +++ b/bootstrap/lib/stdlib/ebin/erl_eval.beam diff --git a/bootstrap/lib/stdlib/ebin/erl_internal.beam b/bootstrap/lib/stdlib/ebin/erl_internal.beam Binary files differindex c571d9f6f3..0b56862c57 100644 --- a/bootstrap/lib/stdlib/ebin/erl_internal.beam +++ b/bootstrap/lib/stdlib/ebin/erl_internal.beam diff --git a/bootstrap/lib/stdlib/ebin/erl_lint.beam b/bootstrap/lib/stdlib/ebin/erl_lint.beam Binary files differindex 3fa4a49c24..ce99e04342 100644 --- a/bootstrap/lib/stdlib/ebin/erl_lint.beam +++ b/bootstrap/lib/stdlib/ebin/erl_lint.beam diff --git a/bootstrap/lib/stdlib/ebin/io_lib.beam b/bootstrap/lib/stdlib/ebin/io_lib.beam Binary files differindex a6403bb708..05894640cb 100644 --- a/bootstrap/lib/stdlib/ebin/io_lib.beam +++ b/bootstrap/lib/stdlib/ebin/io_lib.beam diff --git a/bootstrap/lib/stdlib/ebin/io_lib_format.beam b/bootstrap/lib/stdlib/ebin/io_lib_format.beam Binary files differindex a1acea2cee..9b8d7d8a9e 100644 --- a/bootstrap/lib/stdlib/ebin/io_lib_format.beam +++ b/bootstrap/lib/stdlib/ebin/io_lib_format.beam diff --git a/bootstrap/lib/stdlib/ebin/io_lib_pretty.beam b/bootstrap/lib/stdlib/ebin/io_lib_pretty.beam Binary files differindex dc91c318c5..bd65ecfc30 100644 --- a/bootstrap/lib/stdlib/ebin/io_lib_pretty.beam +++ b/bootstrap/lib/stdlib/ebin/io_lib_pretty.beam diff --git a/bootstrap/lib/stdlib/ebin/ms_transform.beam b/bootstrap/lib/stdlib/ebin/ms_transform.beam Binary files differindex e465ca8d5d..ae3550872f 100644 --- a/bootstrap/lib/stdlib/ebin/ms_transform.beam +++ b/bootstrap/lib/stdlib/ebin/ms_transform.beam diff --git a/bootstrap/lib/stdlib/ebin/proc_lib.beam b/bootstrap/lib/stdlib/ebin/proc_lib.beam Binary files differindex ce36bcf6fc..45f25d7820 100644 --- a/bootstrap/lib/stdlib/ebin/proc_lib.beam +++ b/bootstrap/lib/stdlib/ebin/proc_lib.beam diff --git a/bootstrap/lib/stdlib/ebin/stdlib.app b/bootstrap/lib/stdlib/ebin/stdlib.app index 20c978670e..d660046c77 100644 --- a/bootstrap/lib/stdlib/ebin/stdlib.app +++ b/bootstrap/lib/stdlib/ebin/stdlib.app @@ -20,7 +20,7 @@ %% {application, stdlib, [{description, "ERTS CXC 138 10"}, - {vsn, "3.4.5"}, + {vsn, "3.6"}, {modules, [array, base64, beam_lib, diff --git a/erts/doc/src/erl_nif.xml b/erts/doc/src/erl_nif.xml index 095fc79bdf..bbc12b0a56 100644 --- a/erts/doc/src/erl_nif.xml +++ b/erts/doc/src/erl_nif.xml @@ -2285,7 +2285,7 @@ enif_inspect_iovec(env, max_elements, term, &tail, &iovec); between nodes.</p> <list type="bulleted"> <item> - <p>Two resource terms will compare equal iff they + <p>Two resource terms will compare equal if and only if they would yield the same resource object pointer when passed to <seealso marker="#enif_get_resource"><c>enif_get_resource</c></seealso>.</p> </item> diff --git a/erts/emulator/beam/erl_bif_counters.c b/erts/emulator/beam/erl_bif_counters.c index 001e643857..7c8884ba32 100644 --- a/erts/emulator/beam/erl_bif_counters.c +++ b/erts/emulator/beam/erl_bif_counters.c @@ -41,13 +41,13 @@ * Each logical counter consists of one 64-bit atomic instance per scheduler * plus one instance for the "base value". * - * get() reads all atomics for the counter and return the sum. + * get() reads all atomics for the counter and returns the sum. * add() reads and writes only its own scheduler specific atomic instance. * put() reads all scheduler specific atomics and writes a new base value. */ #define ATOMICS_PER_COUNTER (erts_no_schedulers + 1) -#define COUNTERS_PER_CACHE_LINE (ERTS_CACHE_LINE_SIZE / sizeof(erts_atomic64_t)) +#define ATOMICS_PER_CACHE_LINE (ERTS_CACHE_LINE_SIZE / sizeof(erts_atomic64_t)) typedef struct { @@ -56,7 +56,7 @@ typedef struct UWord ulen; #endif union { - erts_atomic64_t v[COUNTERS_PER_CACHE_LINE]; + erts_atomic64_t v[ATOMICS_PER_CACHE_LINE]; byte cache_line__[ERTS_CACHE_LINE_SIZE]; } u[1]; }CountersRef; @@ -88,7 +88,7 @@ BIF_RETTYPE erts_internal_counters_new_1(BIF_ALIST_1) if (cnt > (ERTS_UWORD_MAX / (sizeof(erts_atomic64_t)*2*ATOMICS_PER_COUNTER))) BIF_ERROR(BIF_P, SYSTEM_LIMIT); - cache_lines = ATOMICS_PER_COUNTER * div_ceil(cnt, COUNTERS_PER_CACHE_LINE); + cache_lines = ATOMICS_PER_COUNTER * div_ceil(cnt, ATOMICS_PER_CACHE_LINE); bytes = offsetof(CountersRef, u) + cache_lines * ERTS_CACHE_LINE_SIZE; mbin = erts_create_magic_binary_x(bytes, counters_destructor, @@ -102,7 +102,7 @@ BIF_RETTYPE erts_internal_counters_new_1(BIF_ALIST_1) #endif ASSERT((byte*)&p->u[cache_lines] <= ((byte*)p + bytes)); for (ui=0; ui < cache_lines; ui++) - for (vi=0; vi < COUNTERS_PER_CACHE_LINE; vi++) + for (vi=0; vi < ATOMICS_PER_CACHE_LINE; vi++) erts_atomic64_init_nob(&p->u[ui].v[vi], 0); hp = HAlloc(BIF_P, ERTS_MAGIC_REF_THING_SIZE); return erts_mk_magic_ref(&hp, &MSO(BIF_P), mbin); @@ -130,8 +130,8 @@ static ERTS_INLINE int get_ref_cnt(Eterm ref, Eterm index, UWord ix, ui, vi; if (!get_ref(ref, &p) || !term_to_UWord(index, &ix) || --ix >= p->arity) return 0; - ui = (ix / COUNTERS_PER_CACHE_LINE) * ATOMICS_PER_COUNTER; - vi = ix % COUNTERS_PER_CACHE_LINE; + ui = (ix / ATOMICS_PER_CACHE_LINE) * ATOMICS_PER_COUNTER + sched_ix; + vi = ix % ATOMICS_PER_CACHE_LINE; ASSERT(ui < p->ulen); *pp = p; *app = &p->u[ui].v[vi]; diff --git a/erts/emulator/beam/erl_gc.c b/erts/emulator/beam/erl_gc.c index 47dd115c82..b4df418cd5 100644 --- a/erts/emulator/beam/erl_gc.c +++ b/erts/emulator/beam/erl_gc.c @@ -681,7 +681,7 @@ garbage_collect(Process* p, ErlHeapFragment *live_hf_end, ErtsMonotonicTime start_time; ErtsSchedulerData *esdp = erts_proc_sched_data(p); erts_aint32_t state; - ERTS_MSACC_PUSH_STATE_M(); + ERTS_MSACC_PUSH_STATE(); #ifdef USE_VM_PROBES DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); #endif @@ -711,7 +711,7 @@ garbage_collect(Process* p, ErlHeapFragment *live_hf_end, else if (p->live_hf_end != ERTS_INVALID_HFRAG_PTR) live_hf_end = p->live_hf_end; - ERTS_MSACC_SET_STATE_CACHED_M(ERTS_MSACC_STATE_GC); + ERTS_MSACC_SET_STATE_CACHED(ERTS_MSACC_STATE_GC); erts_atomic32_read_bor_nob(&p->state, ERTS_PSFLG_GC); if (erts_system_monitor_long_gc != 0) @@ -759,7 +759,7 @@ garbage_collect(Process* p, ErlHeapFragment *live_hf_end, gc_trace_end_tag = am_gc_minor_end; } else { do_major_collection: - ERTS_MSACC_SET_STATE_CACHED_M_X(ERTS_MSACC_STATE_GC_FULL); + ERTS_MSACC_SET_STATE_CACHED_X(ERTS_MSACC_STATE_GC_FULL); if (IS_TRACED_FL(p, F_TRACE_GC)) { trace_gc(p, am_gc_major_start, need, THE_NON_VALUE); } @@ -770,7 +770,7 @@ do_major_collection: p->flags &= ~(F_DIRTY_MAJOR_GC|F_DIRTY_MINOR_GC); DTRACE2(gc_major_end, pidbuf, reclaimed_now); gc_trace_end_tag = am_gc_major_end; - ERTS_MSACC_SET_STATE_CACHED_M_X(ERTS_MSACC_STATE_GC); + ERTS_MSACC_SET_STATE_CACHED_X(ERTS_MSACC_STATE_GC); } reset_active_writer(p); @@ -800,7 +800,7 @@ do_major_collection: /* We have to make sure that we have space for need on the heap */ res = delay_garbage_collection(p, live_hf_end, need, fcalls); - ERTS_MSACC_POP_STATE_M(); + ERTS_MSACC_POP_STATE(); return res; } @@ -843,7 +843,7 @@ do_major_collection: FLAGS(p) &= ~(F_FORCE_GC|F_HIBERNATED); p->live_hf_end = ERTS_INVALID_HFRAG_PTR; - ERTS_MSACC_POP_STATE_M(); + ERTS_MSACC_POP_STATE(); #ifdef CHECK_FOR_HOLES /* diff --git a/erts/emulator/beam/erl_node_tables.c b/erts/emulator/beam/erl_node_tables.c index f4dc60941a..18ed782ae3 100644 --- a/erts/emulator/beam/erl_node_tables.c +++ b/erts/emulator/beam/erl_node_tables.c @@ -421,8 +421,25 @@ static void schedule_delete_dist_entry(DistEntry* dep) * * Note that timeouts do not guarantee thread progress. */ - erts_schedule_thr_prgr_later_op(start_timer_delete_dist_entry, - dep, &dep->later_op); + ErtsSchedulerData *esdp = erts_get_scheduler_data(); + if (esdp && !ERTS_SCHEDULER_IS_DIRTY(esdp)) { + erts_schedule_thr_prgr_later_op(start_timer_delete_dist_entry, + dep, &dep->later_op); + } else { + /* + * Since OTP 20, it's possible that destructor is executed on + * a dirty scheduler. Aux work cannot be done on a dirty + * scheduler, and scheduling any aux work on a dirty scheduler + * makes the scheduler to loop infinitely. + * To avoid this, make a spot jump: schedule this function again + * on a first normal scheduler. It is guaranteed to be always + * online. Since it's a rare event, this shall not pose a big + * utilisation hit. + */ + erts_schedule_misc_aux_work(1, + (void (*)(void *))schedule_delete_dist_entry, + (void *) dep); + } } static void diff --git a/erts/emulator/test/counters_SUITE.erl b/erts/emulator/test/counters_SUITE.erl index 8cc963e3b9..b3f0358c1e 100644 --- a/erts/emulator/test/counters_SUITE.erl +++ b/erts/emulator/test/counters_SUITE.erl @@ -22,12 +22,12 @@ -include_lib("common_test/include/ct.hrl"). -export([suite/0, all/0]). --export([basic/1, bad/1, limits/1, indep/1]). +-export([basic/1, bad/1, limits/1, indep/1, write_concurrency/1]). suite() -> [{ct_hooks,[ts_install_cth]}]. all() -> - [basic, bad, limits, indep]. + [basic, bad, limits, indep, write_concurrency]. basic(Config) when is_list(Config) -> Size = 10, @@ -175,3 +175,60 @@ indep_subber(Ref, I, Val) when Val > -(1 bsl 62) -> indep_subber(Ref, I, Res); indep_subber(_Ref, _I, Val) -> Val. + + + +%% Verify write_concurrency yields correct results. +write_concurrency(Config) when is_list(Config) -> + rand:seed(exs1024s), + io:format("*** SEED: ~p ***\n", [rand:export_seed()]), + NScheds = erlang:system_info(schedulers), + Size = 100, + Ref = counters:new(Size,[write_concurrency]), + Rounds = 1000, + Papa = self(), + Pids = [spawn_opt(fun Worker() -> + receive + {go, Ix, Incr} -> + wc_looper(Rounds, Ref, Ix, Incr), + Papa ! {self(), done, Rounds*Incr}, + Worker(); + stop -> + ok + end + end, + [link, {scheduler, N}]) + || N <- lists:seq(1, NScheds)], + [begin + Base = rand_log64(), + counters:put(Ref, Index, Base), + SendList = [{P,{go, Index, rand_log64()}} || P <- Pids], + [P ! Msg || {P,Msg} <- SendList], + Added = lists:sum([receive {P,done,Contrib} -> Contrib end || P <- Pids]), + Result = mask_sint64(Base+Added), + {_,Result} = {Result, counters:get(Ref, Index)} + end + || Index <- lists:seq(1, Size)], + + [begin unlink(P), P ! stop end || P <- Pids], + ok. + +wc_looper(0, _, _, _) -> + ok; +wc_looper(N, Ref, Ix, Incr) -> + counters:add(Ref, Ix, Incr), + wc_looper(N-1, Ref, Ix, Incr). + +mask_sint64(X) -> + SMask = 1 bsl 63, + UMask = SMask - 1, + (X band UMask) - (X band SMask). + +%% A random signed 64-bit integer +%% with a uniformly distributed number of significant bits. +rand_log64() -> + Uint = round(math:pow(2, rand:uniform()*63)), + case rand:uniform(2) of + 1 -> -Uint; + 2 -> Uint + end. diff --git a/lib/crypto/c_src/otp_test_engine.c b/lib/crypto/c_src/otp_test_engine.c index 34c825059f..2c8cce094e 100644 --- a/lib/crypto/c_src/otp_test_engine.c +++ b/lib/crypto/c_src/otp_test_engine.c @@ -35,7 +35,12 @@ #if OPENSSL_VERSION_NUMBER < PACKED_OPENSSL_VERSION_PLAIN(1,1,0) \ || defined(LIBRESSL_VERSION_NUMBER) -#define OLD +# define OLD +#endif + +#if OPENSSL_VERSION_NUMBER >= PACKED_OPENSSL_VERSION_PLAIN(1,1,0) \ + && !defined(LIBRESSL_VERSION_NUMBER) +# define FAKE_RSA_IMPL #endif #if OPENSSL_VERSION_NUMBER >= PACKED_OPENSSL_VERSION(0,9,8,'o') \ @@ -56,13 +61,41 @@ static const char *test_engine_id = "MD5"; static const char *test_engine_name = "MD5 test engine"; -/* The callback that does the job of fetching keys on demand by the Engine */ -EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data); +#if defined(FAKE_RSA_IMPL) +/*-------- test of private/public keys and RSA in engine ---------*/ +static RSA_METHOD *test_rsa_method = NULL; + +/* Our on "RSA" implementation */ +static int test_rsa_sign(int dtype, const unsigned char *m, + unsigned int m_len, unsigned char *sigret, + unsigned int *siglen, const RSA *rsa); +static int test_rsa_verify(int dtype, const unsigned char *m, + unsigned int m_len, const unsigned char *sigret, + unsigned int siglen, const RSA *rsa); +static int test_rsa_free(RSA *rsa); +#endif /* if defined(FAKE_RSA_IMPL) */ + +/* The callbacks that does the job of fetching keys on demand by the Engine */ +EVP_PKEY* test_privkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data); +EVP_PKEY* test_pubkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data); +EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data, int priv); + +/*----------------------------------------------------------------*/ static int test_init(ENGINE *e) { printf("OTP Test Engine Initializatzion!\r\n"); +#if defined(FAKE_RSA_IMPL) + if ( !RSA_meth_set_finish(test_rsa_method, test_rsa_free) + || !RSA_meth_set_sign(test_rsa_method, test_rsa_sign) + || !RSA_meth_set_verify(test_rsa_method, test_rsa_verify) + ) { + fprintf(stderr, "Setup RSA_METHOD failed\r\n"); + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + /* Load all digest and cipher algorithms. Needed for password protected private keys */ OpenSSL_add_all_ciphers(); OpenSSL_add_all_digests(); @@ -79,6 +112,19 @@ static void add_test_data(unsigned char *md, unsigned int len) } } +#if defined(FAKE_RSA_IMPL) +static int chk_test_data(const unsigned char *md, unsigned int len) +{ + unsigned int i; + + for (i=0; i<len; i++) { + if (md[i] != (unsigned char)(i & 0xff)) + return 0; + } + return 1; +} +#endif /* if defined(FAKE_RSA_IMPL) */ + /* MD5 part */ #undef data #ifdef OLD @@ -184,19 +230,34 @@ static int test_engine_digest_selector(ENGINE *e, const EVP_MD **digest, return ok; } - static int bind_helper(ENGINE * e, const char *id) { - if (!ENGINE_set_id(e, test_engine_id) || - !ENGINE_set_name(e, test_engine_name) || - !ENGINE_set_init_function(e, test_init) || - !ENGINE_set_digests(e, &test_engine_digest_selector) || +#if defined(FAKE_RSA_IMPL) + test_rsa_method = RSA_meth_new("OTP test RSA method", 0); + if (test_rsa_method == NULL) { + fprintf(stderr, "RSA_meth_new failed\r\n"); + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + + if (!ENGINE_set_id(e, test_engine_id) + || !ENGINE_set_name(e, test_engine_name) + || !ENGINE_set_init_function(e, test_init) + || !ENGINE_set_digests(e, &test_engine_digest_selector) /* For testing of key storage in an Engine: */ - !ENGINE_set_load_privkey_function(e, &test_key_load) || - !ENGINE_set_load_pubkey_function(e, &test_key_load) - ) + || !ENGINE_set_load_privkey_function(e, &test_privkey_load) + || !ENGINE_set_load_pubkey_function(e, &test_pubkey_load) + ) return 0; +#if defined(FAKE_RSA_IMPL) + if ( !ENGINE_set_RSA(e, test_rsa_method) ) { + RSA_meth_free(test_rsa_method); + test_rsa_method = NULL; + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + return 1; } @@ -211,24 +272,29 @@ IMPLEMENT_DYNAMIC_BIND_FN(bind_helper); */ int pem_passwd_cb_fun(char *buf, int size, int rwflag, void *password); -EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data) +EVP_PKEY* test_privkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data) { + return test_key_load(eng, id, ui_method, callback_data, 1); +} + +EVP_PKEY* test_pubkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data) { + return test_key_load(eng, id, ui_method, callback_data, 0); +} + +EVP_PKEY* test_key_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data, int priv) { EVP_PKEY *pkey = NULL; FILE *f = fopen(id, "r"); if (!f) { - fprintf(stderr, "%s:%d fopen(%s) failed\r\n", __FILE__,__LINE__,id); - return NULL; + fprintf(stderr, "%s:%d fopen(%s) failed\r\n", __FILE__,__LINE__,id); + return NULL; } - /* First try to read as a private key. If that fails, try to read as a public key: */ - pkey = PEM_read_PrivateKey(f, NULL, pem_passwd_cb_fun, callback_data); - if (!pkey) { - /* ERR_print_errors_fp (stderr); */ - fclose(f); - f = fopen(id, "r"); - pkey = PEM_read_PUBKEY(f, NULL, NULL, NULL); - } + pkey = + priv + ? PEM_read_PrivateKey(f, NULL, pem_passwd_cb_fun, callback_data) + : PEM_read_PUBKEY(f, NULL, NULL, NULL); + fclose(f); if (!pkey) { @@ -278,3 +344,71 @@ int pem_passwd_cb_fun(char *buf, int size, int rwflag, void *password) } #endif + +#if defined(FAKE_RSA_IMPL) +/* RSA sign. This returns a fixed string so the test case can test that it was called + instead of the cryptolib default RSA sign */ + +unsigned char fake_flag[] = {255,3,124,180,35,10,180,151,101,247,62,59,80,122,220, + 142,24,180,191,34,51,150,112,27,43,142,195,60,245,213,80,179}; + +int test_rsa_sign(int dtype, + /* The digest to sign */ + const unsigned char *m, unsigned int m_len, + /* The allocated buffer to fill with the signature */ + unsigned char *sigret, unsigned int *siglen, + /* The key */ + const RSA *rsa) +{ + int slen; + fprintf(stderr, "test_rsa_sign (dtype=%i) called m_len=%u *siglen=%u\r\n", dtype, m_len, *siglen); + if (!sigret) { + fprintf(stderr, "sigret = NULL\r\n"); + return -1; + } + + /* {int i; + fprintf(stderr, "Digest =\r\n"); + for(i=0; i<m_len; i++) + fprintf(stderr, "%i,", m[i]); + fprintf(stderr, "\r\n"); + } */ + + if ((sizeof(fake_flag) == m_len) + && bcmp(m,fake_flag,m_len) == 0) { + printf("To be faked\r\n"); + /* To be faked */ + slen = RSA_size(rsa); + add_test_data(sigret, slen); /* The signature is 0,1,2...255,0,1... */ + *siglen = slen; /* Must set this. Why? */ + return 1; /* 1 = success */ + } + return 0; +} + +int test_rsa_verify(int dtype, + /* The digest to verify */ + const unsigned char *m, unsigned int m_len, + /* The signature */ + const unsigned char *sigret, unsigned int siglen, + /* The key */ + const RSA *rsa) +{ + printf("test_rsa_verify (dtype=%i) called m_len=%u siglen=%u\r\n", dtype, m_len, siglen); + + if ((sizeof(fake_flag) == m_len) + && bcmp(m,fake_flag,m_len) == 0) { + printf("To be faked\r\n"); + return (siglen == RSA_size(rsa)) + && chk_test_data(sigret, siglen); + } + return 0; +} + +static int test_rsa_free(RSA *rsa) +{ + printf("test_rsa_free called\r\n"); + return 1; +} + +#endif /* if defined(FAKE_RSA_IMPL) */ diff --git a/lib/crypto/test/engine_SUITE.erl b/lib/crypto/test/engine_SUITE.erl index 0427923941..42d8edf4d2 100644 --- a/lib/crypto/test/engine_SUITE.erl +++ b/lib/crypto/test/engine_SUITE.erl @@ -51,12 +51,14 @@ all() -> ctrl_cmd_string, ctrl_cmd_string_optional, ensure_load, - {group, engine_stored_key} + {group, engine_stored_key}, + {group, engine_fakes_rsa} ]. groups() -> [{engine_stored_key, [], - [sign_verify_rsa, + [ + sign_verify_rsa, sign_verify_dsa, sign_verify_ecdsa, sign_verify_rsa_pwd, @@ -71,7 +73,10 @@ groups() -> get_pub_from_priv_key_rsa_pwd_bad_pwd, get_pub_from_priv_key_dsa, get_pub_from_priv_key_ecdsa - ]}]. + ]}, + {engine_fakes_rsa, [], [sign_verify_rsa_fake + ]} + ]. init_per_suite(Config) -> @@ -102,7 +107,20 @@ end_per_suite(_Config) -> %%-------------------------------------------------------------------- init_per_group(engine_stored_key, Config) -> - case load_storage_engine(Config) of + group_load_engine(Config, [engine_method_rsa]); +init_per_group(engine_fakes_rsa, Config) -> + case crypto:info_lib() of + [{<<"OpenSSL">>,LibVer,_}] when is_integer(LibVer), LibVer >= 16#10100000 -> + group_load_engine(Config, []); + _ -> + {skip, "Too low OpenSSL cryptolib version"} + end; +init_per_group(_Group, Config0) -> + Config0. + + +group_load_engine(Config, ExcludeMthds) -> + case load_storage_engine(Config, ExcludeMthds) of {ok, E} -> KeyDir = key_dir(Config), [{storage_engine,E}, {storage_dir,KeyDir} | Config]; @@ -115,19 +133,19 @@ init_per_group(engine_stored_key, Config) -> Other -> ct:log("Engine load failed: ~p",[Other]), {fail, "Engine load failed"} - end; -init_per_group(_Group, Config0) -> - Config0. + end. -end_per_group(engine_stored_key, Config) -> + + + + +end_per_group(_, Config) -> case proplists:get_value(storage_engine, Config) of undefined -> ok; E -> ok = crypto:engine_unload(E) - end; -end_per_group(_, _) -> - ok. + end. %%-------------------------------------------------------------------- init_per_testcase(_Case, Config) -> @@ -421,6 +439,9 @@ bad_arguments(Config) when is_list(Config) -> try try crypto:engine_load(fail_engine, [], []) + of + X1 -> + ct:fail("1 Got ~p",[X1]) catch error:badarg -> ok @@ -432,6 +453,11 @@ bad_arguments(Config) when is_list(Config) -> {<<"ID">>, <<"MD5">>}, <<"LOAD">>], []) + of + {error,bad_engine_id} -> + throw(dynamic_engine_unsupported); + X2 -> + ct:fail("2 Got ~p",[X2]) catch error:badarg -> ok @@ -442,13 +468,20 @@ bad_arguments(Config) when is_list(Config) -> {'ID', <<"MD5">>}, <<"LOAD">>], []) + of + {error,bad_engine_id} -> % should have happend in the previous try...catch end! + throw(dynamic_engine_unsupported); + X3 -> + ct:fail("3 Got ~p",[X3]) catch error:badarg -> ok end catch error:notsup -> - {skip, "Engine not supported on this SSL version"} + {skip, "Engine not supported on this SSL version"}; + throw:dynamic_engine_unsupported -> + {skip, "Dynamic Engine not supported"} end end. @@ -650,6 +683,14 @@ sign_verify_rsa(Config) -> key_id => key_id(Config, "rsa_public_key.pem")}, sign_verify(rsa, sha, Priv, Pub). +sign_verify_rsa_fake(Config) -> + %% Use fake engine rsa implementation + Priv = #{engine => engine_ref(Config), + key_id => key_id(Config, "rsa_private_key.pem")}, + Pub = #{engine => engine_ref(Config), + key_id => key_id(Config, "rsa_public_key.pem")}, + sign_verify_fake(rsa, sha256, Priv, Pub). + sign_verify_dsa(Config) -> Priv = #{engine => engine_ref(Config), key_id => key_id(Config, "dsa_private_key.pem")}, @@ -809,13 +850,18 @@ get_pub_from_priv_key_ecdsa(Config) -> %%%================================================================ %%% Help for engine_stored_pub_priv_keys* test cases %%% -load_storage_engine(_Config) -> +load_storage_engine(Config) -> + load_storage_engine(Config, []). + +load_storage_engine(_Config, ExcludeMthds) -> case crypto:get_test_engine() of {ok, Engine} -> try crypto:engine_load(<<"dynamic">>, [{<<"SO_PATH">>, Engine}, <<"LOAD">>], - []) + [], + crypto:engine_get_all_methods() -- ExcludeMthds + ) catch error:notsup -> {error, notsup} @@ -873,10 +919,47 @@ sign_verify(Alg, Sha, KeySign, KeyVerify) -> true -> PlainText = <<"Hej på dig">>, Signature = crypto:sign(Alg, Sha, PlainText, KeySign), - case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of - true -> ok; - _ -> {fail, "Sign-verify error"} + case is_fake(Signature) of + true -> + ct:pal("SIG ~p ~p size ~p~n~p",[Alg,Sha,size(Signature),Signature]), + {fail, "Faked RSA impl used!!"}; + false -> + case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of + true -> ok; + _ -> {fail, "Sign-verify error"} + end + end; + false -> + {skip, lists:concat([Alg," is not supported by cryptolib"])} + end. + + +%%% Use fake engine rsa implementation +sign_verify_fake(Alg, Sha, KeySign, KeyVerify) -> + case pubkey_alg_supported(Alg) of + true -> + PlainText = <<"Fake me!">>, + Signature = crypto:sign(Alg, Sha, PlainText, KeySign), + case is_fake(Signature) of + true -> + case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of + true -> ok; + _ -> {fail, "Sign-verify error"} + end; + false -> + ct:pal("SIG ~p ~p size ~p~n~p",[Alg,Sha,size(Signature),Signature]), + {fail, "Faked impl not used"} end; false -> {skip, lists:concat([Alg," is not supported by cryptolib"])} end. + + +is_fake(Sig) -> is_fake(Sig, 0). + +is_fake(<<>>, _) -> true; +is_fake(<<B,Rest/binary>>, B) -> is_fake(Rest, B+1); +is_fake(_, _) -> false. + + + diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 2bcf137299..556f25f96a 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -290,7 +290,10 @@ logger:error("error happened because: ~p", [Reason]). % Without macro <section> <title>Macros</title> - <p>The following macros are defined:</p> + <p>The following macros are defined in <c>logger.hrl</c>, which + is included in a module with the directive</p> + <code> + -include_lib("kernel/include/logger.hrl").</code> <list> <item><c>?LOG_EMERGENCY(StringOrReport[,Metadata])</c></item> @@ -1214,7 +1217,7 @@ logger:set_process_metadata(maps:merge(logger:get_process_metadata(), Meta)). <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2,3</c></seealso></item> + <c>logger:update_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 1870d2ab79..458e61cef5 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -113,7 +113,10 @@ of functions on the form <c>logger:Level/1,2,3</c>, which are all shortcuts for <seealso marker="logger#log-2"> - <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <p>The macros are defined in <c>logger.hrl</c>, which is included + in a module with the directive</p> + <code>-include_lib("kernel/include/logger.hrl").</code> <p>The difference between using the macros and the exported functions is that macros add location (originator) information to the metadata, and performs lazy evaluation by wrapping the diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 24772fd6c4..d066e263df 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -303,7 +303,7 @@ exit_reason: "It crashed"</code> <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2</c></seealso></item> + <c>logger:update_handler_config/2</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/notes.xml b/lib/kernel/doc/src/notes.xml index 8188ede6a2..bfbaf6ef3e 100644 --- a/lib/kernel/doc/src/notes.xml +++ b/lib/kernel/doc/src/notes.xml @@ -31,6 +31,22 @@ </header> <p>This document describes the changes made to the Kernel application.</p> +<section><title>Kernel 6.1.1</title> + + <section><title>Fixed Bugs and Malfunctions</title> + <list> + <item> + <p> + Fix bug causing net_kernel process crash on connection + attempt from node with name identical to local node.</p> + <p> + Own Id: OTP-15438 Aux Id: ERL-781 </p> + </item> + </list> + </section> + +</section> + <section><title>Kernel 6.1</title> <section><title>Fixed Bugs and Malfunctions</title> diff --git a/lib/kernel/src/kernel.appup.src b/lib/kernel/src/kernel.appup.src index 0c0435e051..e73cea8351 100644 --- a/lib/kernel/src/kernel.appup.src +++ b/lib/kernel/src/kernel.appup.src @@ -16,15 +16,40 @@ %% limitations under the License. %% %% %CopyrightEnd% +%% +%% We allow upgrade from, and downgrade to all previous +%% versions from the following OTP releases: +%% - OTP 20 +%% - OTP 21 +%% +%% We also allow upgrade from, and downgrade to all +%% versions that have branched off from the above +%% stated previous versions. +%% {"%VSN%", - %% Up from - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-21.0 - {<<"6\\.1(\\.[0-9]+)*">>,[restart_new_emulator]}], % OTP-21.1 - %% Down to - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-21.0 - {<<"6\\.1(\\.[0-9]+)*">>,[restart_new_emulator]}] % OTP-21.1 -}. + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}], + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}]}. diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 6bfe658552..5e9faf332c 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -31,7 +31,9 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), + _ = ets:new(Name,[set,protected,named_table, + {read_concurrency,true}, + {write_concurrency,true}]), ets:whereis(Name). delete(Tid,Id) -> diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 2a81458ec8..41e0d51a9d 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -19,59 +19,33 @@ %% -module(logger_disk_log_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks -export([log/2, adding_handler/1, removing_handler/1, changing_config/3, filter_config/1]). -%% handler internal --export([log_handler_info/4]). - %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a disk_log handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added (as a result of calling add/3). --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - disk_log_sync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -80,15 +54,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -96,16 +63,8 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== %%% logger callbacks @@ -113,30 +72,55 @@ reset(Name) -> %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, #{config:=HConfig}=Config1} -> - %% create initial handler state by merging defaults with config - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{file:=File,type:=Type,max_no_bytes:=MNB,max_no_files:=MNF}) -> + case open_disk_log(Name, File, Type, MNB, MNF) of + ok -> + {ok,#{log_opts => #{file => File, + type => Type, + max_no_bytes => MNB, + max_no_files => MNF}, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}}; Error -> Error end. -%%%----------------------------------------------------------------- -%%% Updating handler config -changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> +check_config(Name,set,undefined,HConfig0) -> + HConfig=merge_default_logopts(Name,maps:merge(get_default_config(),HConfig0)), + check_config(HConfig); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> WriteOnce = maps:with([type,file,max_no_files,max_no_bytes],OldHConfig), - ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig), - NewHConfig0 = maps:get(config, NewConfig, #{}), Default = case SetOrUpdate of set -> @@ -146,66 +130,25 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> OldHConfig end, - %% Allow (accidentially) included read-only fields - just overwrite them - NewHConfig = maps:merge(maps:merge(Default,NewHConfig0),ReadOnly), + NewHConfig = maps:merge(Default,NewHConfig0), - %% But fail if write-once fields are changed + %% Fail if write-once fields are changed case maps:with([type,file,max_no_files,max_no_bytes],NewHConfig) of WriteOnce -> - changing_config1(maps:get(handler_pid,OldHConfig), - OldConfig, - NewConfig#{config=>NewHConfig}); + check_config(NewHConfig); Other -> {Old,New} = logger_server:diff_maps(WriteOnce,Other), - {error,{illegal_config_change,#{config=>Old},#{config=>New}}} + {error,{illegal_config_change,?MODULE,Old,New}} end. -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - Error -> Error - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, #{id:=Name}=Config) -> - %% merge handler specific config data - HConfig1 = maps:get(config, Config, #{}), - HConfig2 = maps:merge(get_default_config(), HConfig1), - HConfig3 = merge_default_logopts(Name, HConfig2), - case check_h_config(maps:to_list(HConfig3)) of - ok -> - {ok,Config#{config=>HConfig3}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), +check_config(HConfig) -> case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error + ok -> + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} end. -merge_default_logopts(Name, HConfig) -> - Type = maps:get(type, HConfig, wrap), - {DefaultNoFiles,DefaultNoBytes} = - case Type of - halt -> {undefined,infinity}; - _wrap -> {10,1048576} - end, - {ok,Dir} = file:get_cwd(), - Defaults = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Defaults, HConfig). - check_h_config([{file,File}|Config]) when is_list(File) -> check_h_config(Config); check_h_config([{max_no_files,undefined}|Config]) -> @@ -218,454 +161,59 @@ check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> check_h_config(Config); check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). - -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). - -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +get_default_config() -> + #{}. -%%%----------------------------------------------------------------- -%%% Remove internal fields from configuration -filter_config(#{config:=HConfig}=Config) -> - Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}. +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), + {DefaultNoFiles,DefaultNoBytes} = + case Type of + halt -> {undefined,infinity}; + _wrap -> {10,1048576} + end, + {ok,Dir} = file:get_cwd(), + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== +filesync(Name,_Mode,State) -> + Result = ?disk_log_sync(Name), + maybe_notify_error(Name, filesync, Result, prev_sync_result, State). -init([Name, - Config = #{config := HConfig = #{file:=File, - type:=Type, - max_no_bytes:=MNB, - max_no_files:=MNF}}, - State = #{dl_sync_int := DLSyncInt}]) -> - - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, - case open_disk_log(Name, File, Type, MNB, MNF) of - ok -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - id => Name, - mode_tab => ModeTab, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - last_log_ts => T0, - burst_win_ts => T0, - burst_msg_count => 0, - last_op => sync, - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_disk_log_sync), - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end. +write(Name, Mode, Bin, State) -> + Result = ?disk_log_write(Name, Mode, Bin), + maybe_notify_error(Name, log, Result, prev_log_result, State). -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply, Result, State1}; - -handle_call(disk_log_sync, _From, State = #{id := Name}) -> - State1 = #{prev_sync_result := Result} = disk_log_sync(Name, State), - {reply, Result, State1}; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - _ = gen_server:cast(self(), repeated_disk_log_sync) - end, - {reply, ok, State1}; - false -> - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp(), - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_disk_log_sync, - State = #{id := Name, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - NewState = if LastOp == sync -> - State; - true -> - disk_log_sync(Name, State) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_disk_log_sync]), - NewState#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. +reset_state(_Name, State) -> + State#{prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}. %% The disk log owner must handle status messages from disk_log. -handle_info({disk_log, _Node, _Log, {wrap,_NoLostItems}}, State) -> - {noreply, State}; -handle_info({disk_log, _Node, Log, Info = {truncated,_NoLostItems}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, Info = {blocked_log,_Items}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, full}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(full, PrevInfo, {disk_log,Name,Log,full}), - {noreply, State#{prev_disk_log_info => full}}; -handle_info({disk_log, _Node, Log, Info = {error_status,_Status}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; - -handle_info({'EXIT',_Pid,_Why}, State = #{id := _Name}) -> - {noreply, State}; - -handle_info(_, State) -> - {noreply, State}. - -terminate(Reason, State = #{id := Name}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +handle_info(Name, {disk_log, _Node, Log, Info={truncated,_NoLostItems}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {blocked_log,_Items}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = full}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {error_status,_Status}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(_, _, State) -> + State. + +terminate(Name, _Reason, _State) -> _ = close_disk_log(Name, normal), - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), ok. -code_change(_OldVsn, State, _Extra) -> - {ok, State}. - %%%----------------------------------------------------------------- %%% Internal functions - -%%%----------------------------------------------------------------- -%%% -get_default_config() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -get_init_state() -> - #{dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN}. - -%%%----------------------------------------------------------------- -%%% Add a disk_log handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Config is the logger:handler_config() map. Handler specific parameters -%%% should be provided with a sub map associated with a key named -%%% 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The 'config' sub map will also contain parameters for configuring -%%% the disk_log: -%%% -%%% Config = #{config => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. -%%% -%%% If type == halt, then max_no_files is ignored. -%%% -%%% The disk_log handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerDLH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_dl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this function is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this function is called to write to disk_log -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - dl_sync := DLSync, - dl_sync_int := DLSyncInt, - last_qlen := LastQLen, - last_log_ts := T0}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the disk_log process - %% every DLSyncInt time, to give the handler time between - %% writes so it can keep up with incoming messages - {Status,LastQLen1,State1} = - if DoWrite, DLSync == 0 -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, element(2,process_info(self(),message_queue_len)), - NewState}; - DoWrite -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, LastQLen, NewState}; - not DoWrite -> - ?observe(Name,{flushed,1}), - {dropped, LastQLen, State} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1,State2} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; - true -> - {Mode, BurstMsgCount,State1} - end, - - State3 = - ?update_calls_or_casts(_CallOrCast,1,State2), - State4 = - ?update_max_time(Time, - State3#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - dl_sync => ?update_dl_sync(DLSync,DLSyncInt)}), - {Status,State4}. - - -log_handler_info(Name, Format, Args, State) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = disk_log_write(Name, Bin, State), - ok. - - open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> @@ -698,43 +246,26 @@ close_disk_log(Name, _) -> _ = disk_log:lclose(Name), ok. -disk_log_write(Name, Bin, State) -> - case ?disk_log_blog(Name, Bin) of - ok -> - State#{prev_log_result => ok, last_op => write}; - LogError -> - _ = case maps:get(prev_log_result, State) of - LogError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,log, - LogOpts, - LogError}) - end, - State#{prev_log_result => LogError} - end. - -disk_log_sync(Name, State) -> - case ?disk_log_sync(Name) of - ok -> - State#{prev_sync_result => ok, last_op => sync}; - SyncError -> - _ = case maps:get(prev_sync_result, State) of - SyncError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,filesync, - LogOpts, - SyncError}) - end, - State#{prev_sync_result => SyncError} - end. +disk_log_write(Name, sync, Bin) -> + disk_log:blog(Name, Bin); +disk_log_write(Name, async, Bin) -> + disk_log:balog(Name, Bin). + +%%%----------------------------------------------------------------- +%%% Print error messages, but don't repeat the same message +maybe_notify_error(Name, Op, Result, Key, #{log_opts:=LogOpts}=State) -> + {Result,error_notify_new({Name, Op, LogOpts, Result}, Result, Key, State)}. -error_notify_new(Info,Info, _Term) -> +maybe_notify_status(Name, Log, Info, Key, State) -> + error_notify_new({disk_log, Name, Log, Info}, Info, Key, State). + +error_notify_new(Term, What, Key, State) -> + error_notify_new(What, maps:get(Key,State), Term), + State#{Key => What}. + +error_notify_new(ok,_Prev,_Term) -> + ok; +error_notify_new(Same,Same,_Term) -> ok; -error_notify_new(_Info0,_Info1, Term) -> +error_notify_new(_New,_Prev,Term) -> logger_h_common:error_notify(Term). diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 94c640cb92..74a2d158fc 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -18,26 +18,469 @@ %% %CopyrightEnd% %% -module(logger_h_common). +-behaviour(gen_server). -include("logger_h_common.hrl"). -include("logger_internal.hrl"). --export([log_to_binary/2, - check_common_config/1, - call_cast_or_drop/4, - check_load/1, - limit_burst/1, - kill_if_choked/5, - flush_log_events/0, - flush_log_events/1, - handler_exit/2, - set_restart_flag/2, - unset_restart_flag/2, - cancel_timer/1, - stop_or_restart/3, - overload_levels_ok/1, - error_notify/1, - info_notify/1]). +%% API +-export([start_link/1, info/2, filesync/2, reset/2]). + +%% gen_server and proc_lib callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). + +%% Library functions for handlers +-export([error_notify/1]). + +%%%----------------------------------------------------------------- +-define(CONFIG_KEYS,[sync_mode_qlen, + drop_mode_qlen, + flush_qlen, + burst_limit_enable, + burst_limit_max_count, + burst_limit_window_time, + overload_kill_enable, + overload_kill_qlen, + overload_kill_mem_size, + overload_kill_restart_after, + filesync_repeat_interval]). +-define(READ_ONLY_KEYS,[handler_pid,mode_tab]). + +%%%----------------------------------------------------------------- +%%% API + +%% This function is called by the logger_sup supervisor +start_link(Args) -> + proc_lib:start_link(?MODULE,init,[Args]). + +filesync(Module, Name) -> + call(Module, Name, filesync). + +info(Module, Name) -> + call(Module, Name, info). + +reset(Module, Name) -> + call(Module, Name, reset). + +%%%----------------------------------------------------------------- +%%% Handler being added +adding_handler(#{id:=Name,module:=Module}=Config) -> + HConfig0 = maps:get(config, Config, #{}), + HandlerConfig0 = maps:without(?CONFIG_KEYS,HConfig0), + case Module:check_config(Name,set,undefined,HandlerConfig0) of + {ok,HandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,HandlerConfig), + CommonConfig0 = maps:with(?CONFIG_KEYS,HConfig0), + CommonConfig = maps:merge( + maps:merge(get_default_config(), CommonConfig0), + ModifiedCommon), + case check_config(CommonConfig) of + ok -> + HConfig = maps:merge(CommonConfig,HandlerConfig), + start(Config#{config => HConfig}); + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name, module:=Module}) -> + case whereis(?name_to_reg_name(Module,Name)) of + undefined -> + ok; + Pid -> + %% We don't want to do supervisor:terminate_child here + %% since we need to distinguish this explicit stop from a + %% system termination in order to avoid circular attempts + %% at removing the handler (implying deadlocks and + %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. + _ = gen_server:call(Pid, stop), + ok + end. + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, + #{id:=Name,config:=OldHConfig,module:=Module}, + NewConfig0) -> + NewHConfig0 = maps:get(config, NewConfig0, #{}), + OldHandlerConfig = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,OldHConfig), + NewHandlerConfig0 = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,NewHConfig0), + case Module:check_config(Name, SetOrUpdate, + OldHandlerConfig,NewHandlerConfig0) of + {ok, NewHandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,NewHandlerConfig), + NewCommonConfig0 = maps:with(?CONFIG_KEYS,NewHConfig0), + CommonDefault = + case SetOrUpdate of + set -> + get_default_config(); + update -> + maps:with(?CONFIG_KEYS,OldHConfig) + end, + NewCommonConfig = maps:merge( + maps:merge(CommonDefault,NewCommonConfig0), + ModifiedCommon), + case check_config(NewCommonConfig) of + ok -> + ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), + NewHConfig = maps:merge( + maps:merge(NewCommonConfig,NewHandlerConfig), + ReadOnly), + NewConfig = NewConfig0#{config=>NewHConfig}, + HPid = maps:get(handler_pid,OldHConfig), + case call(HPid, {change_config,NewConfig}) of + ok -> {ok,NewConfig}; + Error -> Error + end; + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config = #{id := Name, + config := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> + %% if the handler has crashed, we must drop this event + %% and hope the handler restarts so we can try again + true = is_process_alive(HPid), + Bin = log_to_binary(LogEvent, Config), + call_cast_or_drop(Name, HPid, ModeTab, Bin). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(#{config:=HConfig}=Config) -> + Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}. + +%%%----------------------------------------------------------------- +%%% Start the handler process +%%% +%%% The process must always exist if the handler is registered with +%%% logger (and must not exist if the handler is not registered). +%%% +%%% The handler process is linked to logger_sup, which is part of the +%%% kernel application's supervision tree. +start(#{id := Name} = Config0) -> + ChildSpec = + #{id => Name, + start => {?MODULE, start_link, [Config0]}, + restart => temporary, + shutdown => 2000, + type => worker, + modules => [?MODULE]}, + case supervisor:start_child(logger_sup, ChildSpec) of + {ok,Pid,Config} -> + ok = logger_handler_watcher:register_handler(Name,Pid), + {ok,Config}; + Error -> + Error + end. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init(#{id := Name, module := Module, + formatter := Formatter, config := HConfig0} = Config0) -> + RegName = ?name_to_reg_name(Module,Name), + register(RegName, self()), + process_flag(trap_exit, true), + process_flag(message_queue_data, off_heap), + + ?init_test_hooks(), + ?start_observation(Name), + + case Module:init(Name, HConfig0) of + {ok,HState} -> + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + T0 = ?timestamp(), + HConfig = HConfig0#{handler_pid => self(), + mode_tab => ModeTab}, + Config = Config0#{config => HConfig}, + proc_lib:init_ack({ok,self(),Config}), + %% Storing common config in state to avoid copying + %% (sending) the config data for each log message + CommonConfig = maps:with(?CONFIG_KEYS,HConfig), + State = + ?merge_with_stats( + CommonConfig#{id => Name, + module => Module, + mode_tab => ModeTab, + mode => async, + ctrl_sync_count => + ?CONTROLLER_SYNC_INTERVAL, + last_qlen => 0, + last_log_ts => T0, + last_op => sync, + burst_win_ts => T0, + burst_msg_count => 0, + formatter => Formatter, + handler_state => HState}), + State1 = set_repeated_filesync(State), + unset_restart_flag(State1), + gen_server:enter_loop(?MODULE, [], State1) + catch + _:Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; + Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end. + +%% This is the synchronous log event. +handle_call({log, Bin}, _From, State) -> + {Result,State1} = do_log(Bin, call, State), + %% Result == ok | dropped + {reply,Result, State1}; + +handle_call(filesync, _From, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState), + {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}; + +handle_call({change_config, #{formatter:=Formatter, config:=NewHConfig}}, _From, + State = #{filesync_repeat_interval := FSyncInt0}) -> + %% In the future, if handler_state must be updated due to config + %% change, then we need to add a callback to Module here. + CommonConfig = maps:with(?CONFIG_KEYS,NewHConfig), + State1 = maps:merge(State, CommonConfig), + State2 = + case maps:get(filesync_repeat_interval, NewHConfig) of + FSyncInt0 -> + State1; + _FSyncInt1 -> + set_repeated_filesync(cancel_repeated_filesync(State1)) + end, + {reply, ok, State2#{formatter:=Formatter}}; + +handle_call(info, _From, State) -> + {reply, State, State}; + +handle_call(reset, _From, + #{id:=Name,module:=Module,handler_state:=HandlerState}=State) -> + State1 = ?merge_with_stats(State), + {reply, ok, State1#{last_qlen => 0, + last_log_ts => ?timestamp(), + handler_state => Module:reset_state(Name,HandlerState)}}; + +handle_call(stop, _From, State) -> + {stop, {shutdown,stopped}, ok, State}. + +%% This is the asynchronous log event. +handle_cast({log, Bin}, State) -> + {_,State1} = do_log(Bin, cast, State), + {noreply, State1}; + +%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this +%% clause gets called repeatedly by the handler. In order to +%% guarantee that a filesync *always* happens after the last log +%% event, the repeat operation must be active! +handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) -> + %% This clause handles a race condition which may occur when + %% config changes filesync_repeat_interval from an integer value + %% to no_repeat. + {noreply,State}; +handle_cast(repeated_filesync, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + last_op := LastOp}) -> + State1 = + if LastOp == sync -> + State; + true -> + {_,HS} = Module:filesync(Name, async, HandlerState), + State#{handler_state => HS, last_op => sync} + end, + {noreply,set_repeated_filesync(State1)}. + +handle_info(Info, #{id := Name, module := Module, + handler_state := HandlerState} = State) -> + {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}. + +terminate(Reason, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + _ = cancel_repeated_filesync(State), + _ = Module:terminate(Name, Reason, HandlerState), + ok = stop_or_restart(Name, Reason, State), + unregister(?name_to_reg_name(Module, Name)), + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + + +%%%----------------------------------------------------------------- +%%% Internal functions +call(Module, Name, Op) when is_atom(Name) -> + call(?name_to_reg_name(Module,Name), Op); +call(_, Name, Op) -> + {error,{badarg,{Op,[Name]}}}. + +call(Server, Msg) -> + try + gen_server:call(Server, Msg, ?DEFAULT_CALL_TIMEOUT) + catch + _:{timeout,_} -> {error,handler_busy} + end. + +%% check for overload between every event (and set Mode to async, +%% sync or drop accordingly), but never flush the whole mailbox +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> + T1 = ?timestamp(), + + %% check if the handler is getting overloaded, or if it's + %% recovering from overload (the check must be done for each + %% event to react quickly to large bursts of events and + %% to ensure that the handler can never end up in drop mode + %% with an empty mailbox, which would stop operation) + {Mode1,QLen,Mem,State1} = check_load(State), + + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + + %% kill the handler if it can't keep up with the load + kill_if_choked(Name, QLen, Mem, State), + + if Mode1 == flush -> + flush(Name, QLen, T1, State1); + true -> + write(Name, Mode1, T1, Bin, CallOrCast, State1) + end. + +%% this clause is called by do_log/3 after an overload check +%% has been performed, where QLen > FlushQLen +flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> + %% flush messages in the mailbox (a limited number in + %% order to not cause long delays) + NewFlushed = flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), + + %% because of the receive loop when flushing messages, the + %% handler will be scheduled out often and the mailbox could + %% grow very large, so we'd better check the queue again here + {_,_QLen1} = process_info(self(), message_queue_len), + ?observe(Name,{max_qlen,_QLen1}), + + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), + + State1 = ?update_max_time(?diff_time(T1,_T0),State), + State2 = ?update_max_qlen(_QLen1,State1), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State2#{mode => ?set_mode(ModeTab,async), + last_qlen => 0, + last_log_ts => T1})}. + +%% this clause is called to write to file +write(Name, Mode, T1, Bin, _CallOrCast, + State = #{module := Module, + handler_state := HandlerState, + mode_tab := ModeTab, + ctrl_sync_count := CtrlSync, + last_qlen := LastQLen, + last_log_ts := T0}) -> + %% check if we need to limit the number of writes + %% during a burst of log events + {DoWrite,State1} = limit_burst(State), + + %% only log synhrounously every ?CONTROLLER_SYNC_INTERVAL time, to + %% give the handler time between writes so it can keep up with + %% incoming messages + {Result,LastQLen1,HandlerState1} = + if DoWrite, CtrlSync == 0 -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, sync, Bin, HandlerState), + {ok,element(2, process_info(self(), message_queue_len)),HS1}; + DoWrite -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, async, Bin, HandlerState), + {ok,LastQLen,HS1}; + not DoWrite -> + ?observe(Name,{flushed,1}), + {dropped,LastQLen,HandlerState} + end, + + %% Check if the time since the previous log event is long enough - + %% and the queue length small enough - to assume the mailbox has + %% been emptied, and if so, do filesync operation and reset mode to + %% async. Note that this is the best we can do to detect an idle + %% handler without setting a timer after each log call/cast. If the + %% time between two consecutive log events is fast and no new + %% event comes in after the last one, idle state won't be detected! + Time = ?diff_time(T1,T0), + State2 = + if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso + (Time > ?IDLE_DETECT_TIME_USEC) -> + {_,HS2} = Module:filesync(Name,async,HandlerState), + State1#{mode => ?change_mode(ModeTab, Mode, async), + burst_msg_count => 0, + handler_state => HS2}; + true -> + State1#{mode => Mode, handler_state => HandlerState1} + end, + State3 = ?update_calls_or_casts(_CallOrCast,1,State2), + State4 = ?update_max_qlen(LastQLen1,State3), + State5 = + ?update_max_time(Time, + State4#{last_qlen := LastQLen1, + last_log_ts => T1, + last_op => write, + ctrl_sync_count => + if CtrlSync==0 -> ?CONTROLLER_SYNC_INTERVAL; + true -> CtrlSync-1 + end}), + {Result,State5}. + +log_handler_info(Name, Format, Args, #{module:=Module, + formatter:=Formatter, + handler_state:=HandlerState}) -> + Config = #{formatter=>Formatter}, + Meta = #{time=>erlang:system_time(microsecond)}, + Bin = log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = Module:write(Name, async, Bin, HandlerState), + ok. %%%----------------------------------------------------------------- %%% Convert log data on any form to binary @@ -94,46 +537,65 @@ string_to_binary(String) -> throw(Error) end. - %%%----------------------------------------------------------------- %%% Check that the configuration term is valid -check_common_config({mode_tab,_Tid}) -> - valid; -check_common_config({handler_pid,Pid}) when is_pid(Pid) -> - valid; - -check_common_config({sync_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({drop_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({flush_qlen,N}) when is_integer(N) -> - valid; - -check_common_config({burst_limit_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({burst_limit_max_count,N}) when is_integer(N) -> - valid; -check_common_config({burst_limit_window_time,N}) when is_integer(N) -> - valid; - -check_common_config({overload_kill_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({overload_kill_qlen,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); - NorA == infinity -> - valid; - -check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); - NorA == no_repeat -> - valid; -check_common_config(_) -> - invalid. +check_config(Config) when is_map(Config) -> + case check_common_config(maps:to_list(Config)) of + ok -> + case overload_levels_ok(Config) of + true -> + ok; + false -> + Faulty = maps:with([sync_mode_qlen, + drop_mode_qlen, + flush_qlen],Config), + {error,{invalid_levels,Faulty}} + end; + Error -> + Error + end. + +check_common_config([{sync_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{drop_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{flush_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{burst_limit_max_count,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_window_time,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{overload_kill_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_mem_size,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_restart_after,NorA}|Config]) + when is_integer(NorA); NorA == infinity -> + check_common_config(Config); +check_common_config([{filesync_repeat_interval,NorA}|Config]) + when is_integer(NorA); NorA == no_repeat -> + check_common_config(Config); +check_common_config([{Key,Value}|_]) -> + {error,#{Key=>Value}}; +check_common_config([]) -> + ok. +get_default_config() -> + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Overload Protection @@ -146,15 +608,13 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> async -> gen_server:cast(HandlerPid, {log,Bin}); sync -> - try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of - %% if return value from call == dropped, the - %% message has been flushed by handler and should - %% therefore not be counted as dropped in stats - ok -> ok; - dropped -> ok - catch - _:{timeout,_} -> - ?observe(_Name,{dropped,1}) + case call(HandlerPid, {log,Bin}) of + ok -> + ok; + _Other -> + %% dropped or {error,handler_busy} + ?observe(_Name,{dropped,1}), + ok end; drop -> ?observe(_Name,{dropped,1}) @@ -165,10 +625,8 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> end, ok. -handler_exit(_Name, Reason) -> - exit(Reason). - -set_restart_flag(Name, Module) -> +set_restart_flag(#{id := Name, module := Module} = State) -> + log_handler_info(Name, "Handler ~p overloaded and stopping", [Name], State), Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), spawn(fun() -> register(Flag, self()), @@ -176,14 +634,14 @@ set_restart_flag(Name, Module) -> end), ok. -unset_restart_flag(Name, Module) -> +unset_restart_flag(#{id := Name, module := Module} = State) -> Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), case whereis(Flag) of undefined -> - false; + ok; Pid -> exit(Pid, kill), - true + log_handler_info(Name, "Handler ~p restarted", [Name], State) end. check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, @@ -221,46 +679,41 @@ check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, ?update_other(flushes,FLUSHES,_NewFlushes, State1#{last_qlen => QLen})}. -limit_burst(#{burst_limit_enable := false}) -> - {true,0,0}; +limit_burst(#{burst_limit_enable := false}=State) -> + {true,State}; limit_burst(#{burst_win_ts := BurstWinT0, burst_msg_count := BurstMsgCount, burst_limit_window_time := BurstLimitWinTime, - burst_limit_max_count := BurstLimitMaxCnt}) -> + burst_limit_max_count := BurstLimitMaxCnt} = State) -> if (BurstMsgCount >= BurstLimitMaxCnt) -> %% the limit for allowed messages has been reached BurstWinT1 = ?timestamp(), case ?diff_time(BurstWinT1,BurstWinT0) of BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> %% we're still within the burst time frame - {false,BurstWinT0,BurstMsgCount}; + {false,?update_other(burst_drops,BURSTS,1,State)}; _BurstCheckTime -> %% burst time frame passed, reset counters - {true,BurstWinT1,0} + {true,State#{burst_win_ts => BurstWinT1, + burst_msg_count => 0}} end; true -> %% the limit for allowed messages not yet reached - {true,BurstWinT0,BurstMsgCount+1} + {true,State#{burst_win_ts => BurstWinT0, + burst_msg_count => BurstMsgCount+1}} end. -kill_if_choked(Name, QLen, Mem, HandlerMod, - State = #{overload_kill_enable := KillIfOL, - overload_kill_qlen := OLKillQLen, - overload_kill_mem_size := OLKillMem}) -> +kill_if_choked(Name, QLen, Mem, State = #{overload_kill_enable := KillIfOL, + overload_kill_qlen := OLKillQLen, + overload_kill_mem_size := OLKillMem}) -> if KillIfOL andalso ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> - HandlerMod:log_handler_info(Name, - "Handler ~p overloaded and stopping", - [Name], State), - set_restart_flag(Name, HandlerMod), - handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}}); + set_restart_flag(State), + exit({shutdown,{overloaded,Name,QLen,Mem}}); true -> ok end. -flush_log_events() -> - flush_log_events(-1). - flush_log_events(Limit) -> process_flag(priority, high), Flushed = flush_log_events(0, Limit), @@ -283,16 +736,29 @@ flush_log_events(N, Limit) -> 0 -> N end. -cancel_timer(TRef) when is_atom(TRef) -> ok; -cancel_timer(TRef) -> timer:cancel(TRef). +set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State) + when is_integer(FSyncInt) -> + {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast, + [self(),repeated_filesync]), + State#{rep_sync_tref=>TRef}; +set_repeated_filesync(State) -> + State. +cancel_repeated_filesync(State) -> + case maps:take(rep_sync_tref,State) of + {TRef,State1} -> + _ = timer:cancel(TRef), + State1; + error -> + State + end. stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, #{overload_kill_restart_after := RestartAfter}) -> %% If we're terminating because of an overload situation (see - %% logger_h_common:kill_if_choked/4), we need to remove the handler - %% and set a restart timer. A separate process must perform this - %% in order to avoid deadlock. + %% kill_if_choked/4), we need to remove the handler and set a + %% restart timer. A separate process must perform this in order to + %% avoid deadlock. HandlerPid = self(), ConfigResult = logger:get_handler_config(Name), RemoveAndRestart = @@ -334,6 +800,3 @@ overload_levels_ok(HandlerConfig) -> error_notify(Term) -> ?internal_log(error, Term). - -info_notify(Term) -> - ?internal_log(info, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index e0a7b6e3ca..261b0a6246 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -137,7 +137,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(set_internal_log(MOD_FUNC), @@ -150,7 +150,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(internal_log(TYPE, TERM), @@ -171,11 +171,11 @@ [{_,ERROR}] -> ERROR catch _:_ -> file:datasync(DEVICE) end). - -define(disk_log_blog(LOG, DATA), - try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of - [{_,ok}] -> disk_log:blog(LOG, DATA); + -define(disk_log_write(LOG, MODE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of + [{_,ok}] -> disk_log_write(LOG, MODE, DATA); [{_,ERROR}] -> ERROR - catch _:_ -> disk_log:blog(LOG, DATA) end). + catch _:_ -> disk_log_write(LOG, MODE, DATA) end). -define(disk_log_sync(LOG), try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of @@ -194,7 +194,7 @@ -define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)). -define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)). -define(file_datasync(DEVICE), file:datasync(DEVICE)). - -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)). + -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)). -define(disk_log_sync(LOG), disk_log:sync(LOG)). -define(DEFAULT_CALL_TIMEOUT, 10000). -endif. @@ -210,7 +210,7 @@ -ifdef(SAVE_STATS). -define(merge_with_stats(STATE), STATE#{flushes => 0, flushed => 0, drops => 0, - casts => 0, calls => 0, + burst_drops => 0, casts => 0, calls => 0, max_qlen => 0, max_time => 0}). -define(update_max_qlen(QLEN, STATE), diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 42e0f5caf4..ebe741e331 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -19,8 +19,6 @@ %% -module(logger_std_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). @@ -28,52 +26,28 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server and proc_lib callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks -export([log/2, adding_handler/1, removing_handler/1, changing_config/3, filter_config/1]). -%% handler internal --export([log_handler_info/4]). - %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a standard handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - filesync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -82,15 +56,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -98,47 +65,75 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== -%%% logger callbacks +%%% logger callbacks - just forward to logger_h_common %%%=================================================================== %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, #{config:=HConfig}=Config1} -> - %% create initial handler state by merging defaults with config - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; +-spec adding_handler(Config) -> {ok,Config} | {error,Reason} when + Config :: logger:handler_config(), + Reason :: term(). + +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +-spec changing_config(SetOrUpdate, OldConfig, NewConfig) -> + {ok,Config} | {error,Reason} when + SetOrUpdate :: set | update, + OldConfig :: logger:handler_config(), + NewConfig :: logger:handler_config(), + Config :: logger:handler_config(), + Reason :: term(). + +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). + +%%%----------------------------------------------------------------- +%%% Handler being removed +-spec removing_handler(Config) -> ok when + Config :: logger:handler_config(). + +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +-spec filter_config(Config) -> Config when + Config :: logger:handler_config(). + +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{type := Type}) -> + case open_log_file(Name, Type) of + {ok,FileCtrlPid} -> + {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -%%%----------------------------------------------------------------- -%%% Updating handler config -changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> +check_config(_Name,set,undefined,NewHConfig) -> + check_config(maps:merge(get_default_config(),NewHConfig)); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> WriteOnce = maps:with([type],OldHConfig), - ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig), - NewHConfig0 = maps:get(config, NewConfig, #{}), Default = case SetOrUpdate of set -> @@ -148,48 +143,24 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> OldHConfig end, - %% Allow (accidentially) included read-only fields - just overwrite them - NewHConfig = maps:merge(maps:merge(Default, NewHConfig0),ReadOnly), + NewHConfig = maps:merge(Default, NewHConfig0), - %% But fail if write-once fields are changed + %% Fail if write-once fields are changed case maps:with([type],NewHConfig) of WriteOnce -> - changing_config1(maps:get(handler_pid,OldHConfig), - OldConfig, - NewConfig#{config=>NewHConfig}); + check_config(NewHConfig); Other -> - {error,{illegal_config_change,#{config=>WriteOnce},#{config=>Other}}} + {error,{illegal_config_change,?MODULE,WriteOnce,Other}} end. -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, Config) -> - %% Merge in defaults on handler level - HConfig0 = maps:get(config, Config, #{}), - HConfig = maps:merge(get_default_config(),HConfig0), +check_config(#{type:=Type}=HConfig) -> case check_h_config(maps:to_list(HConfig)) of + ok when is_atom(Type) -> + {ok,HConfig#{filesync_repeat_interval=>no_repeat}}; ok -> - {ok,Config#{config=>HConfig}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} end. check_h_config([{type,Type} | Config]) when Type == standard_io; @@ -200,219 +171,40 @@ check_h_config([{type,{file,File}} | Config]) when is_list(File) -> check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), is_list(Modes) -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. - -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). - -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). - -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). - -%%%----------------------------------------------------------------- -%%% Remove internal fields from configuration -filter_config(#{config:=HConfig}=Config) -> - Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}. - -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== - -init([Name, Config = #{config := HConfig}, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - case do_init(Name, Type) of - {ok,InitState} -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - mode_tab => ModeTab, - mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_filesync), - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end. - -do_init(Name, Type) -> - case open_log_file(Name, Type) of - {ok,FileCtrlPid} -> - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}}; - Error -> - Error - end. - -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply,Result, State1}; - -handle_call(filesync, _From, State = #{type := Type, - file_ctrl_pid := FileCtrlPid}) -> - if is_atom(Type) -> - {reply, ok, State}; - true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} - end; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - gen_server:cast(self(), repeated_filesync) - end, - {reply, ok, State1}; - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = State1, - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp()}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_filesync, - State = #{type := Type, - file_ctrl_pid := FileCtrlPid, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if not is_atom(Type), is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - if LastOp == sync -> - ok; - true -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_filesync]), - State#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. - -handle_info({'EXIT',Pid,Why}, State = #{id := Name, type := FileInfo}) -> - case maps:get(file_ctrl_pid, State, undefined) of - Pid -> - %% file error, terminate handler - logger_h_common:handler_exit(Name, - {error,{write_failed,FileInfo,Why}}); - _Other -> - %% ignore EXIT - ok - end, - {noreply, State}; - -handle_info(_Info, State) -> - {noreply, State}. - -terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, - type:=_FileInfo}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +get_default_config() -> + #{type => standard_io}. + +filesync(_Name, _Mode, #{type := Type}=State) when is_atom(Type) -> + {ok,State}; +filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) -> + ok = file_ctrl_filesync_async(FileCtrlPid), + {ok,State}; +filesync(_Name, sync, #{file_ctrl_pid := FileCtrlPid} = State) -> + Result = file_ctrl_filesync_sync(FileCtrlPid), + {Result,State}. + +write(_Name, async, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + ok = file_write_async(FileCtrlPid, Bin), + {ok,State}; +write(_Name, sync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + Result = file_write_sync(FileCtrlPid, Bin), + {Result,State}. + +reset_state(_Name, State) -> + State. + +handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) -> + %% file_ctrl_pid died, file error, terminate handler + exit({error,{write_failed,FileInfo,Why}}); +handle_info(_, _, State) -> + State. + +terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> case is_process_alive(FWPid) of true -> unlink(FWPid), @@ -423,17 +215,12 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, ok after ?DEFAULT_CALL_TIMEOUT -> - exit(FWPid, kill) + exit(FWPid, kill), + ok end; false -> ok - end, - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), - ok. - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. + end. %%%=================================================================== %%% Internal functions @@ -441,203 +228,6 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% -get_default_config() -> - #{type => standard_io, - sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -get_init_state() -> - #{file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN}. - -%%%----------------------------------------------------------------- -%%% Add a standard handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The standard handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerStdH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_file_ctrl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this clause is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this clause is called to write to file -write(_Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - file_ctrl_pid := FileCtrlPid, - file_ctrl_sync := FileCtrlSync, - last_qlen := LastQLen, - last_log_ts := T0, - file_ctrl_sync_int := FileCtrlSyncInt}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the file controller process - %% every FileCtrlSyncInt time, to give the handler time between - %% file writes so it can keep up with incoming messages - {Result,LastQLen1} = - if DoWrite, FileCtrlSync == 0 -> - ?observe(_Name,{_CallOrCast,1}), - file_write_sync(FileCtrlPid, Bin, false), - {ok,element(2, process_info(self(), message_queue_len))}; - DoWrite -> - ?observe(_Name,{_CallOrCast,1}), - file_write_async(FileCtrlPid, Bin), - {ok,LastQLen}; - not DoWrite -> - ?observe(_Name,{flushed,1}), - {dropped,LastQLen} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - %% do filesync if necessary - case maps:get(type, State) of - Std when is_atom(Std) -> - ok; - _File -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {?change_mode(ModeTab, Mode, async),0}; - true -> - {Mode,BurstMsgCount} - end, - State1 = - ?update_calls_or_casts(_CallOrCast,1,State), - State2 = - ?update_max_time(Time, - State1#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - last_op => write, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - file_ctrl_sync => - ?update_file_ctrl_sync(FileCtrlSync, - FileCtrlSyncInt)}), - {Result,State2}. - open_log_file(HandlerName, FileInfo) -> case file_ctrl_start(HandlerName, FileInfo) of OK = {ok,_FileCtrlPid} -> OK; @@ -669,19 +259,6 @@ close_log_file(Fd) -> _ = file:close(Fd). -log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = file_write_async(FileCtrlPid, Bin), - ok. - %%%----------------------------------------------------------------- %%% File control process @@ -708,24 +285,19 @@ file_write_async(Pid, Bin) -> Pid ! {log,Bin}, ok. -file_write_sync(Pid, Bin, FileSync) -> - case file_ctrl_call(Pid, {log,self(),Bin,FileSync}) of - {error,Reason} -> - {error,{write_failed,Bin,Reason}}; - Result -> - Result - end. +file_write_sync(Pid, Bin) -> + file_ctrl_call(Pid, {log,Bin}). file_ctrl_filesync_async(Pid) -> Pid ! filesync, ok. file_ctrl_filesync_sync(Pid) -> - file_ctrl_call(Pid, {filesync,self()}). + file_ctrl_call(Pid, filesync). file_ctrl_call(Pid, Msg) -> MRef = monitor(process, Pid), - Pid ! {Msg,MRef}, + Pid ! {Msg,{self(),MRef}}, receive {MRef,Result} -> demonitor(MRef, [flush]), @@ -743,74 +315,40 @@ file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> case do_open_log_file(FileInfo) of {ok,Fd} -> Starter ! {self(),ok}, - file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName); + file_ctrl_loop(Fd, FileName, false, ok, ok, HandlerName); {error,Reason} -> Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; file_ctrl_init(HandlerName, StdDev, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). -file_ctrl_loop(Fd, Type, DevName, Synced, +file_ctrl_loop(Fd, DevName, Synced, PrevWriteResult, PrevSyncResult, HandlerName) -> receive %% asynchronous event {log,Bin} -> - Result = if Type == file -> - write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName); - true -> - io:put_chars(Fd, Bin) - end, - file_ctrl_loop(Fd, Type, DevName, false, + Result = write_to_dev(Fd, Bin, DevName, PrevWriteResult, HandlerName), + file_ctrl_loop(Fd, DevName, false, Result, PrevSyncResult, HandlerName); %% synchronous event - {{log,From,Bin,FileSync},MRef} -> - if Type == file -> - %% check that file hasn't been deleted - CheckFile = - fun() -> {ok,_} = file:read_file_info(DevName) end, - spawn_link(CheckFile), - WResult = write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName), - {Synced1,SResult} = - if not FileSync -> - {false,PrevSyncResult}; - true -> - case sync_dev(Fd, DevName, - PrevSyncResult, HandlerName) of - ok -> {true,ok}; - Error -> {false,Error} - end - end, - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, Synced1, - WResult, SResult, HandlerName); - true -> - _ = io:put_chars(Fd, Bin), - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, false, - ok, PrevSyncResult, HandlerName) - end; + {{log,Bin},{From,MRef}} -> + check_exist(Fd, DevName), + Result = write_to_dev(Fd, Bin, DevName, PrevWriteResult, HandlerName), + From ! {MRef,ok}, + file_ctrl_loop(Fd, DevName, false, + Result, PrevSyncResult, HandlerName); - filesync when not Synced -> - Result = sync_dev(Fd, DevName, PrevSyncResult, HandlerName), - file_ctrl_loop(Fd, Type, DevName, true, + filesync -> + Result = sync_dev(Fd, DevName, Synced, PrevSyncResult, HandlerName), + file_ctrl_loop(Fd, DevName, true, PrevWriteResult, Result, HandlerName); - filesync -> - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, PrevSyncResult, HandlerName); - - {{filesync,From},MRef} -> - Result = if not Synced -> - sync_dev(Fd, DevName, PrevSyncResult, HandlerName); - true -> - ok - end, + {filesync,{From,MRef}} -> + Result = sync_dev(Fd, DevName, Synced, PrevSyncResult, HandlerName), From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, true, + file_ctrl_loop(Fd, DevName, true, PrevWriteResult, Result, HandlerName); stop -> @@ -818,26 +356,30 @@ file_ctrl_loop(Fd, Type, DevName, Synced, stopped end. +check_exist(DevName, DevName) when is_atom(DevName) -> + ok; +check_exist(_Fd, FileName) -> + _ = spawn_link(fun() -> {ok,_} = file:read_file_info(FileName) end), + ok. + +write_to_dev(DevName, Bin, _DevName, _PrevWriteResult, _HandlerName) + when is_atom(DevName) -> + io:put_chars(DevName, Bin); write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> - case ?file_write(Fd, Bin) of - ok -> - ok; - PrevWriteResult -> - %% don't report same error twice - PrevWriteResult; - Error -> - logger_h_common:error_notify({HandlerName,write,FileName,Error}), - Error - end. + Result = ?file_write(Fd, Bin), + maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName). -sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> - case ?file_datasync(Fd) of - ok -> - ok; - PrevSyncResult -> - %% don't report same error twice - PrevSyncResult; - Error -> - logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), - Error - end. +sync_dev(_Fd, _FileName, true, PrevSyncResult, _HandlerName) -> + PrevSyncResult; +sync_dev(Fd, FileName, false, PrevSyncResult, HandlerName) -> + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName). + +maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) -> + ok; +maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) -> + %% don't report same error twice + PrevResult; +maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) -> + logger_h_common:error_notify({HandlerName,Op,FileName,Error}), + Error. diff --git a/lib/kernel/src/net_kernel.erl b/lib/kernel/src/net_kernel.erl index 3cf11fd7b1..a9dc77837e 100644 --- a/lib/kernel/src/net_kernel.erl +++ b/lib/kernel/src/net_kernel.erl @@ -808,7 +808,8 @@ handle_info({AcceptPid, {accept_pending,MyNode,Node,Address,Type}}, State) -> _:_ -> error_logger:error_msg("~n** Cannot get connection id for node ~w~n", [Node]), - AcceptPid ! {self(),{accept_pending,nok_pending}} + AcceptPid ! {self(),{accept_pending,nok_pending}}, + {noreply, State} end end; diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 905c2c52c5..87b8250781 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -332,16 +332,18 @@ errors(Config) -> %%! Check how bad log_opts are handled! {error,{illegal_config_change, - #{config:=#{type:=wrap}}, - #{config:=#{type:=halt}}}} = + logger_disk_log_h, + #{type:=wrap}, + #{type:=halt}}} = logger:update_handler_config(Name1, config, #{type=>halt, file=>LogFile1}), {error,{illegal_config_change, - #{config:=#{file:=LogFile1}}, - #{config:=#{file:="newfilename"}}}} = + logger_disk_log_h, + #{file:=LogFile1}, + #{file:="newfilename"}}} = logger:update_handler_config(Name1, config, #{file=>"newfilename"}), @@ -411,20 +413,25 @@ formatter_fail(cleanup,_Config) -> ok. config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -433,20 +440,17 @@ config_fail(_Config) -> #{filter_default=>log, formatter=>{?MODULE,self()}}), %% can't change the disk log options for a log already in use - {error,{illegal_config_change,_,_}} = + {error,{illegal_config_change,logger_disk_log_h,_,_}} = logger:update_handler_config(?MODULE,config, #{max_no_files=>2}), - %% can't change name of an existing handler - {error,{illegal_config_change,_,_}} = - logger:update_handler_config(?MODULE,id,bad), %% incorrect values of OP params {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), - {error,{invalid_levels,_}} = + {error,{invalid_config,logger_disk_log_h,{invalid_levels,_}}} = logger:update_handler_config(?MODULE,config, HConfig#{sync_mode_qlen=>100, flush_qlen=>99}), %% invalid name of config parameter - {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_disk_log_h,#{filesync_rep_int:=2000}}} = logger:update_handler_config(?MODULE, config, HConfig#{filesync_rep_int => 2000}), ok. @@ -487,10 +491,11 @@ reconfig(Config) -> overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, - log_opts := #{type := ?DISK_LOG_TYPE, - max_no_files := ?DISK_LOG_MAX_NO_FILES, - max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, - file := DiskLogFile}} = + handler_state := + #{log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + file := DiskLogFile}}} = logger_disk_log_h:info(?MODULE), {ok,#{config := #{sync_mode_qlen := ?SYNC_MODE_QLEN, @@ -572,10 +577,11 @@ reconfig(Config) -> max_no_files => 1, max_no_bytes => 1024, file => File}}), - #{log_opts := #{type := halt, - max_no_files := 1, - max_no_bytes := 1024, - file := File}} = + #{handler_state := + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}}} = logger_disk_log_h:info(?MODULE), {ok,#{config := #{type := halt, @@ -596,13 +602,13 @@ reconfig(Config) -> %% You are not allowed to actively set the write once fields %% (type, max_no_files, max_no_bytes, file) in runtime. - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{type=>wrap}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{max_no_files=>2}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{max_no_bytes=>2048}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{file=>"otherfile.log"}), {ok,C7} = logger:get_handler_config(?MODULE), ct:log("C7: ~p",[C7]), @@ -630,16 +636,16 @@ sync(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"first\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"first\n">>}, + {disk_log,sync}]), logger:notice("first", ?domain), %% wait for automatic disk_log_sync check_tracer(?FILESYNC_REPEAT_INTERVAL*2), - %% check that if there's no repeated disk_log_sync active, + %% check that if there's no repeated filesync active, %% a disk_log_sync is still performed when handler goes idle {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, @@ -652,12 +658,12 @@ sync(Config) -> %% triggered by the idle timeout between "fourth" and "fifth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"second\n">>}, - {logger_disk_log_h,disk_log_sync}, - {disk_log,blog,<<"third\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"second\n">>}, + {disk_log,sync}, + {logger_disk_log_h,disk_log_write,<<"third\n">>}, + {disk_log,sync}]), logger:notice("second", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), @@ -667,13 +673,13 @@ sync(Config) -> try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), - %% switch repeated disk_log_sync on and verify that the looping works + %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync}, - %% receive 1 initial repeated_disk_log_sync, then 1 per sec - start_tracer([{logger_disk_log_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, ok = logger:update_handler_config(?MODULE, config, HConfig2), @@ -716,7 +722,7 @@ disk_log_wrap(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]), @@ -734,7 +740,7 @@ disk_log_wrap(Config) -> timer:sleep(1000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] @@ -770,7 +776,7 @@ disk_log_full(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), NoOfChars = 5, Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)], @@ -780,14 +786,18 @@ disk_log_full(Config) -> timer:sleep(2000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), - [{trace,full}, - {trace,{error_status,{error,{full,_}}}}] = Received, + + %% The tail here could be an error_status notification, if the + %% last write was synchronous, but in most cases it will not be + [{trace,full}|_] = Received, + %% [{trace,full}, + %% {trace,{error_status,{error,{full,_}}}}] = Received, ok. disk_log_full(cleanup, _Config) -> dbg:stop_clear(), @@ -819,14 +829,14 @@ disk_log_events(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), [whereis(h_proc_name()) ! E || E <- Events], %% wait for trace messages timer:sleep(2000), dbg:stop_clear(), Received = lists:map(fun({trace,_M,handle_info, - [Got,_]}) -> Got + [_,Got,_]}) -> Got end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), NoOfEvents = length(Events), @@ -849,13 +859,15 @@ write_failure(Config) -> false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]), + ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, + maps:get(handler_state,HState))]), + %% ?check and ?check_no_log in this test only check for internal log events ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of true -> 5500; @@ -864,24 +876,26 @@ write_failure(Config) -> try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this should have caused an internal log ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), - + ok = log_on_remote_node(Node, "No second error printout"), - ?check_no_log, + ?check_no_log, % but don't log same error twice - rpc:call(Node, ?MODULE, set_result, [disk_log_blog, + rpc:call(Node, ?MODULE, set_result, [disk_log_write, {error,{full,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this was a different error, so it should be logged ?check({error,{?STANDARD_HANDLER,log,LogOpts, {error,{full,?STANDARD_HANDLER}}}}), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), ok = log_on_remote_node(Node, "Logged2"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> @@ -901,7 +915,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - LogOpts = maps:get(log_opts, HState), + LogOpts = maps:get(log_opts, maps:get(handler_state,HState)), SyncInt = 500, ok = rpc:call(Node, logger, update_handler_config, @@ -1606,10 +1620,10 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]},Caller}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]},Caller}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); -tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> +tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index b6a09f4980..a1159f280c 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -140,7 +140,7 @@ all() -> ]. add_remove_instance_tty(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => tty}, filter_default=>log, @@ -234,7 +234,7 @@ errors(Config) -> {error, {handler_not_added, - {invalid_config,logger_std_h,{type,faulty_type}}}} = + {invalid_config,logger_std_h,#{type:=faulty_type}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => faulty_type}}), @@ -308,25 +308,30 @@ formatter_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_config,logger_std_h, - {restart_type,bad}}}} = + #{restart_type:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -334,15 +339,15 @@ config_fail(_Config) -> ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{illegal_config_change,#{config:=#{type:=_}},#{config:=#{type:=_}}}} = + {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} = logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), - {error,{invalid_levels,_}} = + {error,{invalid_config,logger_std_h,{invalid_levels,_}}} = logger:set_handler_config(?MODULE,config, #{sync_mode_qlen=>100, flush_qlen=>99}), - {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} = logger:set_handler_config(?MODULE, config, #{filesync_rep_int => 2000}), @@ -468,8 +473,8 @@ reconfig(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -480,7 +485,7 @@ reconfig(Config) -> overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = DefaultInfo = + filesync_repeat_interval := no_repeat} = DefaultInfo = logger_std_h:info(?MODULE), {ok, @@ -496,7 +501,7 @@ reconfig(Config) -> overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = + filesync_repeat_interval := no_repeat} = DefaultHConf}} = logger:get_handler_config(?MODULE), @@ -511,10 +516,10 @@ reconfig(Config) -> overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, overload_kill_restart_after => infinity, - filesync_repeat_interval => no_repeat}), + filesync_repeat_interval => 5000}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -584,7 +589,7 @@ reconfig(Config) -> %% You are not allowed to actively set 'type' in runtime, since %% this is a write once field. - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,logger_std_h,_,_}} = logger:set_handler_config(?MODULE,config,#{type=>standard_io}), {ok,#{config:=C6}} = logger:get_handler_config(?MODULE), ct:log("C6: ~p",[C6]), @@ -620,7 +625,7 @@ file_opts(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{type := OkType} = logger_std_h:info(?MODULE), + #{handler_state := #{type := OkType}} = logger_std_h:info(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -643,10 +648,8 @@ sync(Config) -> %% check repeated filesync happens start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("first", ?domain), @@ -655,10 +658,8 @@ sync(Config) -> %% check that explicit filesync is only done once start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {no_more,500} ]), @@ -679,13 +680,10 @@ sync(Config) -> %% triggered by the idle timeout between "thrid" and "fourth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {logger_std_h, write_to_dev, <<"fourth\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("third", ?domain), %% wait for automatic filesync @@ -697,10 +695,10 @@ sync(Config) -> %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_std_h,handle_cast,repeated_filesync}, - %% receive 1 initial repeated_filesync, then 1 per sec - start_tracer([{logger_std_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), ok = logger:update_handler_config(?MODULE, config, #{filesync_repeat_interval => SyncInt}), @@ -1533,7 +1531,7 @@ start_op_trace() -> {ok,_} = dbg:p(self(), [c]), MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), - {ok,_} = dbg:tp(logger_h_common, check_load, 1, MS1), + {ok,_} = dbg:tpl(logger_h_common, check_load, 1, MS1), {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), @@ -1607,7 +1605,9 @@ analyse(Msgs) -> start_tracer(Trace,Expected) -> Pid = self(), - FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), + FileCtrlPid = maps:get(file_ctrl_pid, + maps:get(handler_state, + logger_std_h:info(?MODULE))), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), @@ -1628,7 +1628,7 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_std_h,handle_cast,[Op|_]}}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, diff --git a/lib/kernel/vsn.mk b/lib/kernel/vsn.mk index df95174c9f..35e6a16a49 100644 --- a/lib/kernel/vsn.mk +++ b/lib/kernel/vsn.mk @@ -1 +1 @@ -KERNEL_VSN = 6.1 +KERNEL_VSN = 6.1.1 diff --git a/lib/observer/src/crashdump_viewer.erl b/lib/observer/src/crashdump_viewer.erl index 0627c15b1c..97bb344cbf 100644 --- a/lib/observer/src/crashdump_viewer.erl +++ b/lib/observer/src/crashdump_viewer.erl @@ -589,9 +589,9 @@ truncated_here(Tag) -> case get(truncated) of true -> case get(last_tag) of - Tag -> % Tag == {TagType,Id} + {Tag,_Pos} -> % Tag == {TagType,Id} true; - {Tag,_Id} -> + {{Tag,_Id},_Pos} -> true; _LastTag -> truncated_earlier(Tag) @@ -846,8 +846,8 @@ do_read_file(File) -> case check_dump_version(Id) of {ok,DumpVsn} -> reset_tables(), - insert_index(Tag,Id,N1+1), - put_last_tag(Tag,""), + insert_index(Tag,Id,Pos=N1+1), + put_last_tag(Tag,"",Pos), DecodeOpts = get_decode_opts(DumpVsn), indexify(Fd,DecodeOpts,Rest,N1), end_progress(), @@ -915,23 +915,11 @@ indexify(Fd,DecodeOpts,Bin,N) -> _ -> insert_index(Tag,Id,NewPos) end, - case put_last_tag(Tag,Id) of - {?proc_heap,LastId} -> - [{_,LastPos}] = lookup_index(?proc_heap,LastId), + case put_last_tag(Tag,Id,NewPos) of + {{?proc_heap,LastId},LastPos} -> ets:insert(cdv_heap_file_chars,{LastId,N+Start+1-LastPos}); - {?literals,[]} -> - case get(truncated_reason) of - undefined -> - [{_,LastPos}] = lookup_index(?literals,[]), - ets:insert(cdv_heap_file_chars, - {literals,N+Start+1-LastPos}); - _ -> - %% Literals are truncated. Make sure we never - %% attempt to read in the literals. (Heaps that - %% references literals will show markers for - %% incomplete heaps, but will otherwise work.) - delete_index(?literals, []) - end; + {{?literals,[]},LastPos} -> + ets:insert(cdv_heap_file_chars,{literals,N+Start+1-LastPos}); _ -> ok end, indexify(Fd,DecodeOpts,Rest,N1); @@ -973,10 +961,18 @@ tag(Fd,<<>>,N,Gat,Di,Now) -> check_if_truncated() -> case get(last_tag) of - {?ende,_} -> + {{?ende,_},_} -> put(truncated,false), put(truncated_proc,false); - TruncatedTag -> + {{?literals,[]},_} -> + put(truncated,true), + put(truncated_proc,false), + %% Literals are truncated. Make sure we never + %% attempt to read in the literals. (Heaps that + %% references literals will show markers for + %% incomplete heaps, but will otherwise work.) + delete_index(?literals, []); + {TruncatedTag,_} -> put(truncated,true), find_truncated_proc(TruncatedTag) end. @@ -984,7 +980,6 @@ check_if_truncated() -> find_truncated_proc({Tag,_Id}) when Tag==?atoms; Tag==?binary; Tag==?instr_data; - Tag==?literals; Tag==?memory_status; Tag==?memory_map -> put(truncated_proc,false); @@ -2870,12 +2865,12 @@ parse_heap_term("Yc"++Line0, Addr, DecodeOpts, D0) -> %Reference-counted binary. SymbolicBin = {'#CDVBin',Start}, Term = cdvbin(Offset, Sz, SymbolicBin), D1 = gb_trees:insert(Addr, Term, D0), - D = gb_trees:insert(Binp, SymbolicBin, D1), + D = gb_trees:enter(Binp, SymbolicBin, D1), {Term,Line,D}; [] -> Term = '#CDVNonexistingBinary', D1 = gb_trees:insert(Addr, Term, D0), - D = gb_trees:insert(Binp, Term, D1), + D = gb_trees:enter(Binp, Term, D1), {Term,Line,D} end; parse_heap_term("Ys"++Line0, Addr, DecodeOpts, D0) -> %Sub binary. @@ -2887,12 +2882,17 @@ parse_heap_term("Ys"++Line0, Addr, DecodeOpts, D0) -> %Sub binary. {Term,Line,D}; parse_heap_term("Mf"++Line0, Addr, DecodeOpts, D0) -> %Flatmap. {Size,":"++Line1} = get_hex(Line0), - {Keys,":"++Line2,D1} = parse_term(Line1, DecodeOpts, D0), - {Values,Line,D2} = parse_tuple(Size, Line2, Addr,DecodeOpts, D1, []), - Pairs = zip_tuples(tuple_size(Keys), Keys, Values, []), - Map = maps:from_list(Pairs), - D = gb_trees:update(Addr, Map, D2), - {Map,Line,D}; + case parse_term(Line1, DecodeOpts, D0) of + {Keys,":"++Line2,D1} when is_tuple(Keys) -> + {Values,Line,D2} = parse_tuple(Size, Line2, Addr,DecodeOpts, D1, []), + Pairs = zip_tuples(tuple_size(Keys), Keys, Values, []), + Map = maps:from_list(Pairs), + D = gb_trees:update(Addr, Map, D2), + {Map,Line,D}; + {Incomplete,_Line,D1} -> + D = gb_trees:insert(Addr, Incomplete, D1), + {Incomplete,"",D} + end; parse_heap_term("Mh"++Line0, Addr, DecodeOpts, D0) -> %Head node in a hashmap. {MapSize,":"++Line1} = get_hex(Line0), {N,":"++Line2} = get_hex(Line1), @@ -3051,7 +3051,7 @@ do_deref_ptr(Lookup, Line, DecodeOpts, D0) -> {Term,Line,D0}; none -> put(incomplete_heap, true), - {['#CDVIncompleteHeap'],Line,D0}; + {'#CDVIncompleteHeap',Line,D0}; {line,Addr,NewLine} -> D = parse_line(Addr, NewLine, DecodeOpts, D0), do_deref_ptr(Lookup, Line, DecodeOpts, D) @@ -3275,13 +3275,13 @@ tag_to_atom(UnknownTag) -> %%%----------------------------------------------------------------- %%% Store last tag for use when truncated, and reason if aborted -put_last_tag(?abort,Reason) -> - %% Don't overwrite the real last tag, and make sure to return - %% the previous last tag. - put(truncated_reason,Reason), - get(last_tag); -put_last_tag(Tag,Id) -> - put(last_tag,{Tag,Id}). +put_last_tag(?abort,Reason,_Pos) -> + %% Don't overwrite the real last tag, and don't return it either, + %% since that would make the caller of this function believe that + %% the tag was complete. + put(truncated_reason,Reason); +put_last_tag(Tag,Id,Pos) -> + put(last_tag,{{Tag,Id},Pos}). %%%----------------------------------------------------------------- %%% Fetch next chunk from crashdump file diff --git a/lib/observer/test/crashdump_helper.erl b/lib/observer/test/crashdump_helper.erl index 576d112154..d5d3649525 100644 --- a/lib/observer/test/crashdump_helper.erl +++ b/lib/observer/test/crashdump_helper.erl @@ -64,6 +64,7 @@ n1_proc(Creator,_N2,Pid2,Port2,_L) -> put(ref,Ref), put(pid,Pid), put(bin,Bin), + put(proc_bins,create_proc_bins()), put(bins,create_binaries()), put(sub_bin,SubBin), put(sub_bins,create_sub_binaries(get(bins))), @@ -119,6 +120,23 @@ create_sub_binary(Bin, Start, LenSub) -> <<_:Start/bytes,Sub:Len/bytes,_/bytes>> = Bin, Sub. +create_proc_bins() -> + Parent = self(), + Pid = + spawn( + fun() -> + %% Just reverse the list here, so this binary is not + %% confused with the one created in n1_proc/5 above, + %% which is used for testing truncation (see + %% crashdump_viewer_SUITE:truncate_dump_binary/1) + Bin = list_to_binary(lists:reverse(lists:seq(1, 255))), + <<A:65/bytes,B:65/bytes,C/bytes>> = Bin, + Parent ! {self(),{A,B,C}} + end), + receive + {Pid,ProcBins} -> ProcBins + end. + %%% %%% Test dumping of maps. Dumping of maps only from OTP 20.2. %%% diff --git a/lib/observer/test/crashdump_viewer_SUITE.erl b/lib/observer/test/crashdump_viewer_SUITE.erl index ed53c46a0d..8c5e618f4a 100644 --- a/lib/observer/test/crashdump_viewer_SUITE.erl +++ b/lib/observer/test/crashdump_viewer_SUITE.erl @@ -400,6 +400,13 @@ special(File,Procs) -> crashdump_viewer:expand_binary({SOffset,SSize,SPos}), io:format(" expand binary ok",[]), + ProcBins = proplists:get_value(proc_bins,Dict), + {['#CDVBin',0,65,ProcBin], + ['#CDVBin',65,65,ProcBin], + ['#CDVBin',130,125,ProcBin]} = ProcBins, + io:format(" ProcBins ok",[]), + + Binaries = crashdump_helper:create_binaries(), verify_binaries(Binaries, proplists:get_value(bins,Dict)), io:format(" binaries ok",[]), diff --git a/lib/reltool/src/reltool_utils.erl b/lib/reltool/src/reltool_utils.erl index 060a0912f9..2afa386cb3 100644 --- a/lib/reltool/src/reltool_utils.erl +++ b/lib/reltool/src/reltool_utils.erl @@ -47,6 +47,9 @@ call/2, cast/2, reply/3]). +%% For testing +-export([erl_libs/2]). + -include_lib("kernel/include/file.hrl"). -include_lib("wx/include/wx.hrl"). -include("reltool.hrl"). @@ -55,7 +58,15 @@ root_dir() -> code:root_dir(). erl_libs() -> - string:lexemes(os:getenv("ERL_LIBS", ""), ":;"). + erl_libs(os:getenv("ERL_LIBS", ""), os:type()). + +erl_libs(ErlLibs, OsType) when is_list(ErlLibs) -> + Sep = + case OsType of + {win32, _} -> ";"; + _ -> ":" + end, + string:lexemes(ErlLibs, Sep). lib_dirs(Dir) -> case erl_prim_loader:list_dir(Dir) of diff --git a/lib/reltool/test/reltool_server_SUITE.erl b/lib/reltool/test/reltool_server_SUITE.erl index 4e1937d479..9ee61b595d 100644 --- a/lib/reltool/test/reltool_server_SUITE.erl +++ b/lib/reltool/test/reltool_server_SUITE.erl @@ -142,7 +142,8 @@ all() -> use_selected_vsn, use_selected_vsn_relative_path, non_standard_vsn_id, - undefined_regexp]. + undefined_regexp, + windows_erl_libs]. groups() -> []. @@ -2546,10 +2547,21 @@ undefined_regexp(_Config) -> ok. %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% Checks that reltool_utils can correctly read Windows ERL_LIBS + +windows_erl_libs(_Config) -> + WinErlLibs = + "C:\\Program Files\\Erlang Libs;C:\\Program Files\\More Erlang Libs", + Ret = reltool_utils:erl_libs(WinErlLibs, {win32, nt}), + ?m(["C:\\Program Files\\Erlang Libs","C:\\Program Files\\More Erlang Libs"], + Ret), + ok. + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Library functions erl_libs() -> - string:lexemes(os:getenv("ERL_LIBS", ""), ":;"). + reltool_utils:erl_libs(). datadir(Config) -> %% Removes the trailing slash... diff --git a/lib/ssh/test/ssh_engine_SUITE.erl b/lib/ssh/test/ssh_engine_SUITE.erl index c2e6ac1fee..3adb23acdb 100644 --- a/lib/ssh/test/ssh_engine_SUITE.erl +++ b/lib/ssh/test/ssh_engine_SUITE.erl @@ -126,10 +126,17 @@ simple_connect(Config) -> load_engine() -> case crypto:get_test_engine() of {ok, Engine} -> - try crypto:engine_load(<<"dynamic">>, + try + %% The test engine has it's own fake rsa sign/verify that + %% you don't want to use, so exclude it from methods to load: + Methods = + crypto:engine_get_all_methods() -- [engine_method_rsa], + crypto:engine_load(<<"dynamic">>, [{<<"SO_PATH">>, Engine}, <<"LOAD">>], - []) + [], + Methods + ) catch error:notsup -> {error, notsup} diff --git a/lib/ssl/test/ssl_engine_SUITE.erl b/lib/ssl/test/ssl_engine_SUITE.erl index e6c82d3eb5..a39a62e550 100644 --- a/lib/ssl/test/ssl_engine_SUITE.erl +++ b/lib/ssl/test/ssl_engine_SUITE.erl @@ -46,10 +46,17 @@ init_per_suite(Config) -> ssl_test_lib:clean_start(), case crypto:get_test_engine() of {ok, EngineName} -> - try crypto:engine_load(<<"dynamic">>, - [{<<"SO_PATH">>, EngineName}, - <<"LOAD">>], - []) of + try + %% The test engine has it's own fake rsa sign/verify that + %% you don't want to use, so exclude it from methods to load: + Methods = + crypto:engine_get_all_methods() -- [engine_method_rsa], + crypto:engine_load(<<"dynamic">>, + [{<<"SO_PATH">>, EngineName}, + <<"LOAD">>], + [], + Methods) + of {ok, Engine} -> [{engine, Engine} |Config]; {error, Reason} -> diff --git a/make/otp_patch_solve_forward_merge_version b/make/otp_patch_solve_forward_merge_version index b8626c4cff..7ed6ff82de 100644 --- a/make/otp_patch_solve_forward_merge_version +++ b/make/otp_patch_solve_forward_merge_version @@ -1 +1 @@ -4 +5 diff --git a/otp_versions.table b/otp_versions.table index 7bea0fbb2d..269fdf66d6 100644 --- a/otp_versions.table +++ b/otp_versions.table @@ -1,3 +1,4 @@ +OTP-21.1.4 : kernel-6.1.1 # asn1-5.0.7 common_test-1.16.1 compiler-7.2.7 crypto-4.3.3 debugger-4.2.6 dialyzer-3.3.1 diameter-2.1.6 edoc-0.9.4 eldap-1.2.6 erl_docgen-0.8.1 erl_interface-3.10.4 erts-10.1.3 et-1.6.3 eunit-2.3.7 ftp-1.0.1 hipe-3.18.1 inets-7.0.2 jinterface-1.9.1 megaco-3.18.4 mnesia-4.15.5 observer-2.8.1 odbc-2.12.2 os_mon-2.4.6 otp_mibs-1.2.1 parsetools-2.1.8 public_key-1.6.3 reltool-0.7.7 runtime_tools-1.13.1 sasl-3.2.1 snmp-5.2.12 ssh-4.7.1 ssl-9.0.3 stdlib-3.6 syntax_tools-2.1.6 tftp-1.0.1 tools-3.0.1 wx-1.8.5 xmerl-1.3.18 : OTP-21.1.3 : erts-10.1.3 # asn1-5.0.7 common_test-1.16.1 compiler-7.2.7 crypto-4.3.3 debugger-4.2.6 dialyzer-3.3.1 diameter-2.1.6 edoc-0.9.4 eldap-1.2.6 erl_docgen-0.8.1 erl_interface-3.10.4 et-1.6.3 eunit-2.3.7 ftp-1.0.1 hipe-3.18.1 inets-7.0.2 jinterface-1.9.1 kernel-6.1 megaco-3.18.4 mnesia-4.15.5 observer-2.8.1 odbc-2.12.2 os_mon-2.4.6 otp_mibs-1.2.1 parsetools-2.1.8 public_key-1.6.3 reltool-0.7.7 runtime_tools-1.13.1 sasl-3.2.1 snmp-5.2.12 ssh-4.7.1 ssl-9.0.3 stdlib-3.6 syntax_tools-2.1.6 tftp-1.0.1 tools-3.0.1 wx-1.8.5 xmerl-1.3.18 : OTP-21.1.2 : compiler-7.2.7 erts-10.1.2 public_key-1.6.3 # asn1-5.0.7 common_test-1.16.1 crypto-4.3.3 debugger-4.2.6 dialyzer-3.3.1 diameter-2.1.6 edoc-0.9.4 eldap-1.2.6 erl_docgen-0.8.1 erl_interface-3.10.4 et-1.6.3 eunit-2.3.7 ftp-1.0.1 hipe-3.18.1 inets-7.0.2 jinterface-1.9.1 kernel-6.1 megaco-3.18.4 mnesia-4.15.5 observer-2.8.1 odbc-2.12.2 os_mon-2.4.6 otp_mibs-1.2.1 parsetools-2.1.8 reltool-0.7.7 runtime_tools-1.13.1 sasl-3.2.1 snmp-5.2.12 ssh-4.7.1 ssl-9.0.3 stdlib-3.6 syntax_tools-2.1.6 tftp-1.0.1 tools-3.0.1 wx-1.8.5 xmerl-1.3.18 : OTP-21.1.1 : compiler-7.2.6 eldap-1.2.6 erts-10.1.1 ssl-9.0.3 # asn1-5.0.7 common_test-1.16.1 crypto-4.3.3 debugger-4.2.6 dialyzer-3.3.1 diameter-2.1.6 edoc-0.9.4 erl_docgen-0.8.1 erl_interface-3.10.4 et-1.6.3 eunit-2.3.7 ftp-1.0.1 hipe-3.18.1 inets-7.0.2 jinterface-1.9.1 kernel-6.1 megaco-3.18.4 mnesia-4.15.5 observer-2.8.1 odbc-2.12.2 os_mon-2.4.6 otp_mibs-1.2.1 parsetools-2.1.8 public_key-1.6.2 reltool-0.7.7 runtime_tools-1.13.1 sasl-3.2.1 snmp-5.2.12 ssh-4.7.1 stdlib-3.6 syntax_tools-2.1.6 tftp-1.0.1 tools-3.0.1 wx-1.8.5 xmerl-1.3.18 : |