diff options
19 files changed, 251 insertions, 29 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/priv/stats_descriptions.cfg b/src/couch_log/priv/stats_descriptions.cfg index 31e41614b..c1cea1628 100644 --- a/src/couch_log/priv/stats_descriptions.cfg +++ b/src/couch_log/priv/stats_descriptions.cfg @@ -46,3 +46,11 @@ {type, counter}, {desc, <<"number of logged warning messages">>} ]}. +{[couch_log, level, report], [ + {type, counter}, + {desc, <<"number of logged report messages">>} +]}. +{[couch_log, level, report_error], [ + {type, counter}, + {desc, <<"number of failed report messages">>} +]}. diff --git a/src/couch_log/src/couch_log.erl b/src/couch_log/src/couch_log.erl index b8a1ca4bd..595143962 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,6 +49,18 @@ alert(Fmt, Args) -> log(alert, Fmt, Args). -spec emergency(string(), list()) -> ok. emergency(Fmt, Args) -> log(emergency, Fmt, Args). +-spec report(string(), map()) -> true | false. +report(ReportId, Meta) when is_map(Meta) -> + couch_stats:increment_counter([couch_log, level, report]), + case couch_log_formatter:format_report(self(), ReportId, Meta) of + {error, emsgtoolong} -> + couch_stats:increment_counter([couch_log, level, report_error]), + false; + {ok, Entry} -> + ok = couch_log_server:log(Entry), + true + end. + -spec set_level(atom() | string() | integer()) -> true. set_level(Level) -> config:set("log", "level", couch_log_util:level_to_string(Level)). 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..91b64ad7d 100644 --- a/src/couch_log/src/couch_log_formatter.erl +++ b/src/couch_log/src/couch_log_formatter.erl @@ -21,6 +21,8 @@ format/3, format/1, + format_report/3, + format_reason/1, format_mfa/1, format_trace/1, @@ -31,6 +33,30 @@ -define(DEFAULT_TRUNCATION, 1024). +-define(REPORT_LEVEL, report). + +format_report(Pid, Type, Meta) -> + MaxMsgSize = couch_log_config:get(max_message_size), + Msg = + case format_meta(Meta) of + "" -> ""; + Msg0 -> ["[", Msg0, "]"] + end, + case iolist_size(Msg) > MaxMsgSize of + true -> + {error, emsgtoolong}; + false -> + Entry = #log_entry{ + level = couch_log_util:level_to_atom(?REPORT_LEVEL), + pid = Pid, + msg = Msg, + msg_id = couch_log_util:get_msg_id(), + time_stamp = couch_log_util:iso8601_timestamp(), + type = Type + }, + {ok, Entry} + end. + format(Level, Pid, Fmt, Args) -> #log_entry{ level = couch_log_util:level_to_atom(Level), @@ -436,3 +462,40 @@ 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) when is_number(Term) -> + io_lib:format("~s=~p", [K, Term]); +to_str(K, Term) when is_binary(Term) -> + io_lib:format("~s=\"~s\"", [K, 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..68aaa85ce 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. diff --git a/src/couch_log/src/couch_log_writer_file.erl b/src/couch_log/src/couch_log_writer_file.erl index 7341f08dc..68250d8ee 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_stderr.erl b/src/couch_log/src/couch_log_writer_stderr.erl index 01e350971..5c2c761fa 100644 --- a/src/couch_log/src/couch_log_writer_stderr.erl +++ b/src/couch_log/src/couch_log_writer_stderr.erl @@ -27,14 +27,14 @@ init() -> terminate(_, _St) -> ok. -write(Entry, St) -> +write(#log_entry{type = Type} = 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 = "[~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..76357bf3e 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", "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 = St#st.report_level}, 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-DB@~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..29d5497f6 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,24 @@ truncate_test() -> Entry = couch_log_formatter:format(info, self(), Msg), ?assert(length(Entry#log_entry.msg) =< 16000). +format_report_etoolong_test() -> + Payload = lists:flatten(lists:duplicate(1048576, "a")), + Resp = couch_log_formatter:format_report(self(), report123, #{ + msg => Payload + }), + ?assertEqual({error, emsgtoolong}, Resp). + +format_report_test() -> + {ok, Entry} = couch_log_formatter:format_report(self(), report123, #{ + foo => 123, + bar => "barStr", + baz => baz + }), + % NOTE: this currently hardcodes the ordering of the keys, however, map + % key order is not guaranteed and this may break. + Formatted = "[foo=123 baz=\"baz\" bar=\"barStr\"]", + ?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..19d2826ec 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,40 @@ 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", "]"], + 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-DB@12345 foo=1]\n", string:join(Rest, " ")), + ?assert(meck:called(gen_udp, close, 1)), + ?assert(meck:validate(gen_udp)). + facility_test() -> Names = [ "kern", diff --git a/src/mango/src/mango_cursor_nouveau.erl b/src/mango/src/mango_cursor_nouveau.erl index 8a6525cca..7cdad20cd 100644 --- a/src/mango/src/mango_cursor_nouveau.erl +++ b/src/mango/src/mango_cursor_nouveau.erl @@ -122,10 +122,10 @@ execute(Cursor, UserFun, UserAcc) -> JsonBM = nouveau_bookmark:pack(FinalBM), Arg = {add_key, bookmark, JsonBM}, {_Go, FinalUserAcc} = UserFun(Arg, LastUserAcc), - FinalUserAcc0 = mango_execution_stats:maybe_add_stats( + {FinalUserAcc0, Stats1} = mango_execution_stats:maybe_add_stats( Opts, UserFun, Stats0, FinalUserAcc ), - FinalUserAcc1 = mango_cursor:maybe_add_warning(UserFun, Cursor, Stats0, FinalUserAcc0), + FinalUserAcc1 = mango_cursor:maybe_add_warning(UserFun, Cursor, Stats1, FinalUserAcc0), {ok, FinalUserAcc1} end. diff --git a/src/mango/src/mango_cursor_text.erl b/src/mango/src/mango_cursor_text.erl index 959603316..7454aebfd 100644 --- a/src/mango/src/mango_cursor_text.erl +++ b/src/mango/src/mango_cursor_text.erl @@ -127,10 +127,12 @@ execute(Cursor, UserFun, UserAcc) -> JsonBM = dreyfus_bookmark:pack(FinalBM), Arg = {add_key, bookmark, JsonBM}, {_Go, FinalUserAcc} = UserFun(Arg, LastUserAcc), - FinalUserAcc0 = mango_execution_stats:maybe_add_stats( + {FinalUserAcc0, Stats1} = mango_execution_stats:maybe_add_stats( Opts, UserFun, Stats0, FinalUserAcc ), - FinalUserAcc1 = mango_cursor:maybe_add_warning(UserFun, Cursor, Stats0, FinalUserAcc0), + %% This needs Stats1 as log_end is called in maybe_add_stats + mango_execution_stats:log_stats(Stats1), + FinalUserAcc1 = mango_cursor:maybe_add_warning(UserFun, Cursor, Stats1, FinalUserAcc0), {ok, FinalUserAcc1} end. diff --git a/src/mango/src/mango_cursor_view.erl b/src/mango/src/mango_cursor_view.erl index eec8dc4fe..d5cffbc5c 100644 --- a/src/mango/src/mango_cursor_view.erl +++ b/src/mango/src/mango_cursor_view.erl @@ -229,11 +229,13 @@ execute(#cursor{db = Db, index = Idx, execution_stats = Stats} = Cursor0, UserFu Arg = {add_key, bookmark, NewBookmark}, {_Go, FinalUserAcc} = UserFun(Arg, LastCursor#cursor.user_acc), Stats0 = LastCursor#cursor.execution_stats, - FinalUserAcc0 = mango_execution_stats:maybe_add_stats( + {FinalUserAcc0, Stats1} = mango_execution_stats:maybe_add_stats( Opts, UserFun, Stats0, FinalUserAcc ), + %% This needs Stats1 as log_end is called in maybe_add_stats + mango_execution_stats:log_stats(Stats1), FinalUserAcc1 = mango_cursor:maybe_add_warning( - UserFun, Cursor, Stats0, FinalUserAcc0 + UserFun, Cursor, Stats1, FinalUserAcc0 ), {ok, FinalUserAcc1}; {error, Reason} -> diff --git a/src/mango/src/mango_execution_stats.erl b/src/mango/src/mango_execution_stats.erl index 0db3edf5f..66104e89e 100644 --- a/src/mango/src/mango_execution_stats.erl +++ b/src/mango/src/mango_execution_stats.erl @@ -14,6 +14,7 @@ -export([ to_json/1, + to_map/1, incr_keys_examined/1, incr_docs_examined/1, incr_docs_examined/2, @@ -21,6 +22,7 @@ incr_results_returned/1, log_start/1, log_end/1, + log_stats/1, maybe_add_stats/4 ]). @@ -35,6 +37,15 @@ to_json(Stats) -> {execution_time_ms, Stats#execution_stats.executionTimeMs} ]}. +to_map(Stats) -> + #{ + total_keys_examined => Stats#execution_stats.totalKeysExamined, + total_docs_examined => Stats#execution_stats.totalDocsExamined, + total_quorum_docs_examined => Stats#execution_stats.totalQuorumDocsExamined, + results_returned => Stats#execution_stats.resultsReturned, + execution_time_ms => Stats#execution_stats.executionTimeMs + }. + incr_keys_examined(Stats) -> Stats#execution_stats{ totalKeysExamined = Stats#execution_stats.totalKeysExamined + 1 @@ -74,13 +85,24 @@ log_end(Stats) -> maybe_add_stats(Opts, UserFun, Stats0, UserAcc) -> Stats1 = log_end(Stats0), couch_stats:update_histogram([mango, query_time], Stats1#execution_stats.executionTimeMs), + %% TODO: add rows read when we collect the stats + %% TODO: add docs vs quorum docs + chttpd_stats:incr_reads(Stats1#execution_stats.totalDocsExamined), + + FinalAcc = + case couch_util:get_value(execution_stats, Opts) of + true -> + JSONValue = to_json(Stats1), + Arg = {add_key, execution_stats, JSONValue}, + {_Go, FinalUserAcc} = UserFun(Arg, UserAcc), + FinalUserAcc; + _ -> + UserAcc + end, + {FinalAcc, Stats1}. - case couch_util:get_value(execution_stats, Opts) of - true -> - JSONValue = to_json(Stats1), - Arg = {add_key, execution_stats, JSONValue}, - {_Go, FinalUserAcc} = UserFun(Arg, UserAcc), - FinalUserAcc; - _ -> - UserAcc - end. +log_stats(Stats) -> + MStats0 = to_map(Stats), + Nonce = list_to_binary(couch_log_util:get_msg_id()), + MStats1 = MStats0#{nonce => Nonce}, + couch_log:report("mango-stats", MStats1). |