This is an automated email from the ASF dual-hosted git repository. chewbranca pushed a commit to branch add-report-logging in repository https://gitbox.apache.org/repos/asf/couchdb.git
commit f6ea77301becd8c481a0f14e828eeeec7d1f1180 Author: ILYA Khlopotov <[email protected]> AuthorDate: Fri Sep 23 13:49:56 2022 -0700 Add couch_log:report/2 to log structured data --- src/couch_log/include/couch_log.hrl | 3 +- src/couch_log/src/couch_log.erl | 13 ++++- src/couch_log/src/couch_log_config.erl | 3 ++ src/couch_log/src/couch_log_config_dyn.erl | 1 + src/couch_log/src/couch_log_formatter.erl | 56 ++++++++++++++++++++-- src/couch_log/src/couch_log_sup.erl | 2 + src/couch_log/src/couch_log_util.erl | 13 ++++- src/couch_log/src/couch_log_writer_file.erl | 2 +- src/couch_log/src/couch_log_writer_syslog.erl | 28 +++++++++-- src/couch_log/test/eunit/couch_log_config_test.erl | 18 +++++++ .../test/eunit/couch_log_formatter_test.erl | 11 +++++ src/couch_log/test/eunit/couch_log_writer_ets.erl | 7 +-- .../test/eunit/couch_log_writer_syslog_test.erl | 42 ++++++++++++++++ 13 files changed, 182 insertions(+), 17 deletions(-) diff --git a/src/couch_log/include/couch_log.hrl b/src/couch_log/include/couch_log.hrl index fa544a88b..eabc9a7e3 100644 --- a/src/couch_log/include/couch_log.hrl +++ b/src/couch_log/include/couch_log.hrl @@ -15,7 +15,8 @@ pid, msg, msg_id, - time_stamp + time_stamp, + type }). diff --git a/src/couch_log/src/couch_log.erl b/src/couch_log/src/couch_log.erl index b8a1ca4bd..d519082ce 100644 --- a/src/couch_log/src/couch_log.erl +++ b/src/couch_log/src/couch_log.erl @@ -21,7 +21,7 @@ critical/2, alert/2, emergency/2, - + report/2, set_level/1 ]). @@ -49,16 +49,25 @@ alert(Fmt, Args) -> log(alert, Fmt, Args). -spec emergency(string(), list()) -> ok. emergency(Fmt, Args) -> log(emergency, Fmt, Args). +-spec report(string(), map()) -> ok. +report(ReportId, Meta) when is_map(Meta) -> + couch_stats:increment_counter([couch_log, level, report]), + Entry = couch_log_formatter:format(report, self(), ReportId, "", [], Meta), + ok = couch_log_server:report(Entry). + -spec set_level(atom() | string() | integer()) -> true. set_level(Level) -> config:set("log", "level", couch_log_util:level_to_string(Level)). -spec log(atom(), string(), list()) -> ok. log(Level, Fmt, Args) -> + log(Level, undefined, Fmt, Args, #{}). + +log(Level, Type, Fmt, Args, Meta) -> case couch_log_util:should_log(Level) of true -> couch_stats:increment_counter([couch_log, level, Level]), - Entry = couch_log_formatter:format(Level, self(), Fmt, Args), + Entry = couch_log_formatter:format(Level, self(), Type, Fmt, Args, Meta), ok = couch_log_server:log(Entry); false -> ok diff --git a/src/couch_log/src/couch_log_config.erl b/src/couch_log/src/couch_log_config.erl index 925973178..c3fd8fe85 100644 --- a/src/couch_log/src/couch_log_config.erl +++ b/src/couch_log/src/couch_log_config.erl @@ -43,6 +43,7 @@ entries() -> [ {level, "level", "info"}, {level_int, "level", "info"}, + {report_level, "report_level", "info"}, {max_message_size, "max_message_size", "16000"}, {strip_last_msg, "strip_last_msg", "true"}, {filter_fields, "filter_fields", "[pid, registered_name, error_info, messages]"} @@ -87,6 +88,8 @@ forms() -> transform(level, LevelStr) -> couch_log_util:level_to_atom(LevelStr); +transform(report_level, LevelStr) -> + couch_log_util:level_to_atom(LevelStr); transform(level_int, LevelStr) -> Level = couch_log_util:level_to_atom(LevelStr), couch_log_util:level_to_integer(Level); diff --git a/src/couch_log/src/couch_log_config_dyn.erl b/src/couch_log/src/couch_log_config_dyn.erl index ff781d3a0..1b1b3bd8e 100644 --- a/src/couch_log/src/couch_log_config_dyn.erl +++ b/src/couch_log/src/couch_log_config_dyn.erl @@ -22,6 +22,7 @@ ]). get(level) -> info; +get(report_level) -> info; get(level_int) -> 2; get(max_message_size) -> 16000; get(strip_last_msg) -> true; diff --git a/src/couch_log/src/couch_log_formatter.erl b/src/couch_log/src/couch_log_formatter.erl index 2ce0fba6d..e1110b6d0 100644 --- a/src/couch_log/src/couch_log_formatter.erl +++ b/src/couch_log/src/couch_log_formatter.erl @@ -17,6 +17,7 @@ -module(couch_log_formatter). -export([ + format/6, format/4, format/3, format/1, @@ -32,12 +33,26 @@ -define(DEFAULT_TRUNCATION, 1024). format(Level, Pid, Fmt, Args) -> + format(Level, Pid, undefined, Fmt, Args, #{}). + +format(report = Level, Pid, Type, Fmt, Args, Meta) -> #log_entry{ level = couch_log_util:level_to_atom(Level), pid = Pid, - msg = maybe_truncate(Fmt, Args), + msg = maybe_truncate(Fmt, Args, Meta, false), msg_id = couch_log_util:get_msg_id(), - time_stamp = couch_log_util:iso8601_timestamp() + time_stamp = couch_log_util:iso8601_timestamp(), + type = Type + }; + +format(Level, Pid, Type, Fmt, Args, Meta) -> + #log_entry{ + level = couch_log_util:level_to_atom(Level), + pid = Pid, + msg = maybe_truncate(Fmt, Args, Meta, true), + msg_id = couch_log_util:get_msg_id(), + time_stamp = couch_log_util:iso8601_timestamp(), + type = Type }. format(Level, Pid, Msg) -> @@ -365,9 +380,16 @@ format_args([H | T], FmtAcc, ArgsAcc) -> {Str, _} = couch_log_trunc_io:print(H, 100), format_args(T, ["~s" | FmtAcc], [Str | ArgsAcc]). -maybe_truncate(Fmt, Args) -> +maybe_truncate(Fmt, Args, Meta, TruncateMeta) -> MaxMsgSize = couch_log_config:get(max_message_size), - couch_log_trunc_io:format(Fmt, Args, MaxMsgSize). + case format_meta(Meta) of + "" -> + couch_log_trunc_io:format(Fmt, Args, MaxMsgSize); + MetaStr when TruncateMeta -> + couch_log_trunc_io:format(["[", MetaStr, "] " | Fmt], Args, MaxMsgSize); + MetaStr -> + ["[", MetaStr, "] " | couch_log_trunc_io:format(Fmt, Args, MaxMsgSize)] + end. maybe_truncate(Msg) -> MaxMsgSize = couch_log_config:get(max_message_size), @@ -436,3 +458,29 @@ get_value(Key, List, Default) -> supervisor_name({local, Name}) -> Name; supervisor_name(Name) -> Name. + +format_meta(Meta) -> + %% https://www.rfc-editor.org/rfc/rfc5424.html#section-6.3 + %% iut="3" eventSource="Application" eventID="1011" + string:join(maps:fold(fun(K, V, Acc) -> + [to_str(K, V) | Acc] + end, [], Meta), " "). + +%% passing complex terms as meta value is a mistake so we are going +%% to eat it, because we cannot bubble up errors from logger +%% Therefore following are not supported +%% - lists +%% - tuples +%% - maps +%% However we are not going to try to distinguish lists from string +%% Atoms would be printed as strings +to_str(K, _) when not (is_list(K) or is_atom(K)) -> + ""; +to_str(K, Term) when is_list(Term) -> + io_lib:format("~s=\"~s\"", [K, Term]); +to_str(_K, Term) when is_tuple(Term) -> + ""; +to_str(_K, Term) when is_map(Term) -> + ""; +to_str(K, Term) -> + io_lib:format("~s=\"~p\"", [K, Term]). diff --git a/src/couch_log/src/couch_log_sup.erl b/src/couch_log/src/couch_log_sup.erl index 0167192d8..a7c581ebd 100644 --- a/src/couch_log/src/couch_log_sup.erl +++ b/src/couch_log/src/couch_log_sup.erl @@ -59,6 +59,8 @@ handle_config_change("log", Key, _, _, S) -> case Key of "level" -> couch_log_config:reconfigure(); + "report_level" -> + couch_log_config:reconfigure(); "max_message_size" -> couch_log_config:reconfigure(); "strip_last_msg" -> diff --git a/src/couch_log/src/couch_log_util.erl b/src/couch_log/src/couch_log_util.erl index 8be11e12d..ae3b68df2 100644 --- a/src/couch_log/src/couch_log_util.erl +++ b/src/couch_log/src/couch_log_util.erl @@ -21,7 +21,9 @@ level_to_atom/1, level_to_string/1, - string_p/1 + string_p/1, + + maybe_format_type/1 ]). -include("couch_log.hrl"). @@ -29,6 +31,8 @@ -spec should_log(#log_entry{} | atom()) -> boolean(). should_log(#log_entry{level = Level}) -> should_log(Level); +should_log(report) -> + should_log(couch_log_config:get(report_level)); should_log(Level) -> level_to_integer(Level) >= couch_log_config:get(level_int). @@ -145,3 +149,10 @@ string_p1([]) -> true; string_p1(_) -> false. + +maybe_format_type(#log_entry{type = undefined} = Entry) -> + Entry; +maybe_format_type(#log_entry{type = Type, msg = [$[ | Msg]} = Entry) -> + Entry#log_entry{msg = ["[", Type, " " | Msg]}; +maybe_format_type(#log_entry{} = Entry) -> + Entry. \ No newline at end of file diff --git a/src/couch_log/src/couch_log_writer_file.erl b/src/couch_log/src/couch_log_writer_file.erl index 9b7255050..7fd92bd90 100644 --- a/src/couch_log/src/couch_log_writer_file.erl +++ b/src/couch_log/src/couch_log_writer_file.erl @@ -77,7 +77,7 @@ write(Entry, St) -> msg = Msg, msg_id = MsgId, time_stamp = TimeStamp - } = Entry, + } = couch_log_util:maybe_format_type(Entry), Fmt = "[~s] ~s ~s ~p ~s ", Args = [ couch_log_util:level_to_string(Level), diff --git a/src/couch_log/src/couch_log_writer_syslog.erl b/src/couch_log/src/couch_log_writer_syslog.erl index b95cf018c..d99550bde 100644 --- a/src/couch_log/src/couch_log_writer_syslog.erl +++ b/src/couch_log/src/couch_log_writer_syslog.erl @@ -28,7 +28,9 @@ hostname, os_pid, appid, - facility + facility, + report_level, + enterprise_number }). -define(SYSLOG_VERSION, 1). @@ -55,7 +57,7 @@ init() -> undefined end end, - + Level = list_to_atom(config:get("log", "syslog_report_level", "info")), {ok, #st{ socket = Socket, host = Host, @@ -63,20 +65,36 @@ init() -> hostname = net_adm:localhost(), os_pid = os:getpid(), appid = config:get("log", "syslog_appid", "couchdb"), - facility = get_facility(config:get("log", "syslog_facility", "local2")) + facility = get_facility(config:get("log", "syslog_facility", "local2")), + report_level = Level, + enterprise_number = config:get("log", "syslog_enterprise_number") }}. terminate(_Reason, St) -> gen_udp:close(St#st.socket). -write(Entry, St) -> +write(#log_entry{level = report} = Entry, #st{enterprise_number = undefined} = St) -> + do_write(Entry#log_entry{level = error}, St); +write(#log_entry{level = report, type = Type} = Entry0, #st{report_level = Level} = St) -> + % append @${enterprise_number} to the type to conform with + % https://www.rfc-editor.org/rfc/rfc5424.html#page-15 + TypeSDID = lists:flatten(io_lib:format("~s@~s", [Type, St#st.enterprise_number])), + Entry = Entry0#log_entry{ + type = TypeSDID, + level = Level + }, + do_write(Entry, St); +write(#log_entry{} = Entry, #st{} = St) -> + do_write(Entry, St). + +do_write(Entry, St) -> #log_entry{ level = Level, pid = Pid, msg = Msg, msg_id = MsgId, time_stamp = TimeStamp - } = Entry, + } = couch_log_util:maybe_format_type(Entry), Fmt = "<~B>~B ~s ~s ~s ~p ~s - ", Args = [ St#st.facility bor get_level(Level), diff --git a/src/couch_log/test/eunit/couch_log_config_test.erl b/src/couch_log/test/eunit/couch_log_config_test.erl index df7cdf977..3cf56b003 100644 --- a/src/couch_log/test/eunit/couch_log_config_test.erl +++ b/src/couch_log/test/eunit/couch_log_config_test.erl @@ -20,6 +20,7 @@ couch_log_config_test_() -> {setup, fun couch_log_test_util:start/0, fun couch_log_test_util:stop/1, [ ?T(check_level), + ?T(check_report_level), ?T(check_max_message_size), ?T(check_bad_level), ?T(check_bad_max_message_size), @@ -29,6 +30,23 @@ couch_log_config_test_() -> ?T(check_bad_filter_fields) ]}. +check_report_level() -> + % Default report_level is info + ?assertEqual(info, couch_log_config:get(report_level)), + couch_log_test_util:with_config_listener(fun() -> + config:set("log", "report_level", "emerg"), + couch_log_test_util:wait_for_config(), + ?assertEqual(emergency, couch_log_config:get(report_level)), + + config:set("log", "report_level", "debug"), + couch_log_test_util:wait_for_config(), + ?assertEqual(debug, couch_log_config:get(report_level)), + + config:delete("log", "report_level"), + couch_log_test_util:wait_for_config(), + ?assertEqual(info, couch_log_config:get(report_level)) + end). + check_level() -> % Default level is info ?assertEqual(info, couch_log_config:get(level)), diff --git a/src/couch_log/test/eunit/couch_log_formatter_test.erl b/src/couch_log/test/eunit/couch_log_formatter_test.erl index a4de74990..00a1a2c96 100644 --- a/src/couch_log/test/eunit/couch_log_formatter_test.erl +++ b/src/couch_log/test/eunit/couch_log_formatter_test.erl @@ -25,6 +25,17 @@ truncate_test() -> Entry = couch_log_formatter:format(info, self(), Msg), ?assert(length(Entry#log_entry.msg) =< 16000). +format_report_test() -> + MsgFmt = "This is a reason: ~r", + Reason = {foo, [{x, k, 3}, {c, d, 2}]}, + Entry = couch_log_formatter:format(report, self(), report123, MsgFmt, [Reason], #{ + foo => 123, + bar => "barStr", + baz => baz + }), + Formatted = "[foo=\"123\" baz=\"baz\" bar=\"barStr\"] This is a reason: foo at x:k/3 <= c:d/2", + ?assertEqual(Formatted, lists:flatten(Entry#log_entry.msg)). + format_reason_test() -> MsgFmt = "This is a reason: ~r", Reason = {foo, [{x, k, 3}, {c, d, 2}]}, diff --git a/src/couch_log/test/eunit/couch_log_writer_ets.erl b/src/couch_log/test/eunit/couch_log_writer_ets.erl index 7ddb9f39e..385aa9676 100644 --- a/src/couch_log/test/eunit/couch_log_writer_ets.erl +++ b/src/couch_log/test/eunit/couch_log_writer_ets.erl @@ -30,9 +30,10 @@ terminate(_, _St) -> ok. write(Entry0, St) -> - Entry = Entry0#log_entry{ - msg = lists:flatten(Entry0#log_entry.msg), - time_stamp = lists:flatten(Entry0#log_entry.time_stamp) + Entry1 = couch_log_util:maybe_format_type(Entry0), + Entry = Entry1#log_entry{ + msg = lists:flatten(Entry1#log_entry.msg), + time_stamp = lists:flatten(Entry1#log_entry.time_stamp) }, Ignored = application:get_env(couch_log, ignored_pids, []), case lists:member(Entry#log_entry.pid, Ignored) of diff --git a/src/couch_log/test/eunit/couch_log_writer_syslog_test.erl b/src/couch_log/test/eunit/couch_log_writer_syslog_test.erl index 5a3f89520..bfac2bc92 100644 --- a/src/couch_log/test/eunit/couch_log_writer_syslog_test.erl +++ b/src/couch_log/test/eunit/couch_log_writer_syslog_test.erl @@ -31,6 +31,12 @@ couch_log_writer_syslog_test_() -> [{gen_udp, [unstick]}], fun check_udp_send/0 ) + end, + fun() -> + couch_log_test_util:with_meck( + [{gen_udp, [unstick]}], + fun check_format/0 + ) end ]}. @@ -81,6 +87,42 @@ check_udp_send() -> ?assert(meck:called(gen_udp, close, 1)), ?assert(meck:validate(gen_udp)). +check_format() -> + meck:expect(gen_udp, open, 1, {ok, socket}), + meck:expect(gen_udp, send, 4, ok), + meck:expect(gen_udp, close, fun(socket) -> ok end), + config:set("log", "syslog_host", "localhost"), + config:set("log", "syslog_enterprise_number", "12345"), + try + Entry = #log_entry{ + level = report, + pid = list_to_pid("<0.1.0>"), + msg = "[foo=1] stuff", + msg_id = "msg_id", + time_stamp = "time_stamp", + type = report123 + }, + {ok, St} = ?WRITER:init(), + {ok, NewSt} = ?WRITER:write(Entry, St), + ok = ?WRITER:terminate(stop, NewSt) + after + config:delete("log", "syslog_host") + end, + + ?assert(meck:called(gen_udp, open, 1)), + Packet = lists:flatten(meck:capture(first, gen_udp, send, '_', 4)), + [SeverityAndVsn, TS, _Host, AppId, Pid, MsgId, _ | Rest] = string:split(Packet, " ", all), + ?assertEqual("<150>1", SeverityAndVsn), + ?assertEqual("time_stamp", TS), + ?assertEqual("couchdb", AppId), + ?assertEqual("msg_id", MsgId), + ?assert(is_pid(catch list_to_pid(Pid))), + ?assertEqual("[report123@12345 foo=1] stuff\n", string:join(Rest, " ")), + ?assert(meck:called(gen_udp, close, 1)), + ?assert(meck:validate(gen_udp)). + + + facility_test() -> Names = [ "kern",
