Update report logging format and logic

8 files changed, 62 insertions, 19 deletions

diff --git a/src/couch_log/src/couch_log.erl b/src/couch_log/src/couch_log.erl
index 3d198994c..bd954e58d 100644
--- a/src/couch_log/src/couch_log.erl
+++ b/src/couch_log/src/couch_log.erl
@@ -21,6 +21,7 @@
     critical/2,
     alert/2,
     emergency/2,
+    report/2,
     report/4,
     set_level/1
 ]).
@@ -49,8 +50,18 @@ 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) ->
+    report(ReportId, "", [], Meta).
+
 -spec report(string(), string(), list(), map()) -> ok.
-report(ReportId, Fmt, Args, Meta) when is_map(Meta) ->
+report(ReportId, Fmt, Args, Meta0) when is_map(Meta0) ->
+    Meta = case maps:is_key(type, Meta0) of
+        true ->
+            Meta0;
+        false ->
+            Meta0#{type => ReportId}
+    end,
     couch_stats:increment_counter([couch_log, level, report]),
     Entry = couch_log_formatter:format(report, self(), ReportId, Fmt, Args, Meta),
     %%ok = couch_log_server:report(Entry).
diff --git a/src/couch_log/src/couch_log_formatter.erl b/src/couch_log/src/couch_log_formatter.erl
index e1110b6d0..bf7571975 100644
--- a/src/couch_log/src/couch_log_formatter.erl
+++ b/src/couch_log/src/couch_log_formatter.erl
@@ -380,6 +380,17 @@ format_args([H | T], FmtAcc, ArgsAcc) ->
     {Str, _} = couch_log_trunc_io:print(H, 100),
     format_args(T, ["~s" | FmtAcc], [Str | ArgsAcc]).
 
+maybe_truncate("", [], Meta, TruncateMeta) ->
+    MaxMsgSize = couch_log_config:get(max_message_size),
+    case format_meta(Meta) of
+        "" ->
+            "";
+        MetaStr when TruncateMeta and length(MetaStr) > MaxMsgSize ->
+            %% TODO: what to do when meta formatted data is too large?
+            error(what_to_do_here);
+        MetaStr ->
+            ["[", MetaStr, "]"]
+    end;
 maybe_truncate(Fmt, Args, Meta, TruncateMeta) ->
     MaxMsgSize = couch_log_config:get(max_message_size),
     case format_meta(Meta) of
@@ -388,7 +399,9 @@ maybe_truncate(Fmt, Args, Meta, TruncateMeta) ->
         MetaStr when TruncateMeta ->
             couch_log_trunc_io:format(["[", MetaStr, "] " | Fmt], Args, MaxMsgSize);
         MetaStr ->
-            ["[", MetaStr, "] " | couch_log_trunc_io:format(Fmt, Args, MaxMsgSize)]
+            %% Subtract 3 for open/close bracket and space added below
+            MsgLength = length(MetaStr) + 3,
+            ["[", MetaStr, "] " | couch_log_trunc_io:format(Fmt, Args, MaxMsgSize - MsgLength)]
     end.
 
 maybe_truncate(Msg) ->
@@ -482,5 +495,7 @@ to_str(_K, Term) when is_tuple(Term) ->
     "";
 to_str(_K, Term) when is_map(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_util.erl b/src/couch_log/src/couch_log_util.erl
index ae3b68df2..4773ca46c 100644
--- a/src/couch_log/src/couch_log_util.erl
+++ b/src/couch_log/src/couch_log_util.erl
@@ -154,5 +154,7 @@ 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{type = Type, msg = [_|_]=Msg} = Entry) ->
+    Entry#log_entry{msg = [Type, " " | Msg]};
 maybe_format_type(#log_entry{} = Entry) ->
-    Entry.
\ No newline at end of file
+    Entry.
diff --git a/src/couch_log/src/couch_log_writer_stderr.erl b/src/couch_log/src/couch_log_writer_stderr.erl
index 01e350971..50aaaed9f 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 d99550bde..567e623ba 100644
--- a/src/couch_log/src/couch_log_writer_syslog.erl
+++ b/src/couch_log/src/couch_log_writer_syslog.erl
@@ -93,9 +93,10 @@ do_write(Entry, St) ->
         pid = Pid,
         msg = Msg,
         msg_id = MsgId,
+        type = Type,
         time_stamp = TimeStamp
     } = couch_log_util:maybe_format_type(Entry),
-    Fmt = "<~B>~B ~s ~s ~s ~p ~s - ",
+    Fmt = "<~B>~B ~s ~s ~s ~p ~p ~s - ",
     Args = [
         St#st.facility bor get_level(Level),
         ?SYSLOG_VERSION,
@@ -103,6 +104,7 @@ do_write(Entry, St) ->
         St#st.hostname,
         St#st.appid,
         Pid,
+        Type,
         MsgId
     ],
     Pre = io_lib:format(Fmt, Args),
diff --git a/src/mango/src/mango_cursor_text.erl b/src/mango/src/mango_cursor_text.erl
index 959603316..88bf7b39c 100644
--- a/src/mango/src/mango_cursor_text.erl
+++ b/src/mango/src/mango_cursor_text.erl
@@ -127,9 +127,11 @@ 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
             ),
+            %% 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),
             {ok, FinalUserAcc1}
     end.
diff --git a/src/mango/src/mango_cursor_view.erl b/src/mango/src/mango_cursor_view.erl
index 412ee62bb..d5cffbc5c 100644
--- a/src/mango/src/mango_cursor_view.erl
+++ b/src/mango/src/mango_cursor_view.erl
@@ -229,12 +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,
-                    mango_execution_stats:log_stats(Stats0),
-                    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 2752f5a71..746cc4835 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,
@@ -36,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
@@ -75,11 +85,11 @@ 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: validate rows/reads assignments
-    chttpd_stats:incr_rows(Stats1#execution_stats.totalDocsExamined),
-    chttpd_stats:incr_reads(Stats1#execution_stats.totalQuorumDocsExamined),
+    %% TODO: add rows read when we collect the stats
+    %% TODO: add docs vs quorum docs
+    chttpd_stats:incr_reads(Stats1#execution_stats.totalDocsExamined),
 
-    case couch_util:get_value(execution_stats, Opts) of
+    FinalAcc = case couch_util:get_value(execution_stats, Opts) of
         true ->
             JSONValue = to_json(Stats1),
             Arg = {add_key, execution_stats, JSONValue},
@@ -87,11 +97,11 @@ maybe_add_stats(Opts, UserFun, Stats0, UserAcc) ->
             FinalUserAcc;
         _ ->
             UserAcc
-    end.
+    end,
+    {FinalAcc, Stats1}.
 
 log_stats(Stats) ->
-    {JStats0} = to_json(Stats),
+    MStats0 = to_map(Stats),
     Nonce = list_to_binary(couch_log_util:get_msg_id()),
-    JStats = {[{<<"nonce">>, Nonce} | JStats0]},
-	%% TODO: switch to report
-    couch_log:report("FIXME-reportid", "[ASDFMARKER] GOT MANGO EXEC STATS: ~s", [binary_to_list(jiffy:encode(JStats))], #{}).
+    MStats1 = MStats0#{nonce => Nonce},
+    couch_log:report("mango-stats", MStats1).