You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@couchdb.apache.org by ch...@apache.org on 2023/01/17 17:41:28 UTC
[couchdb] 01/02: Add couch_log:report/2 to log structured data
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 <ii...@apache.org>
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",