You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@couchdb.apache.org by ko...@apache.org on 2021/04/22 20:46:08 UTC
[couchdb] 02/03: Produce structured logging reports
This is an automated email from the ASF dual-hosted git repository.
kocolosk pushed a commit to branch new-logger
in repository https://gitbox.apache.org/repos/asf/couchdb.git
commit 898050d63f2c2e92b8827adf717c1867344d85a5
Author: Adam Kocoloski <ko...@apache.org>
AuthorDate: Thu Apr 22 15:13:51 2021 -0400
Produce structured logging reports
---
src/aegis/src/aegis_server.erl | 3 +
src/chttpd/include/chttpd.hrl | 1 +
src/chttpd/src/chttpd.erl | 56 +++++++-
src/chttpd/src/chttpd_auth_cache.erl | 23 ++++
src/chttpd/src/chttpd_cors.erl | 7 +
src/chttpd/src/chttpd_db.erl | 17 +++
src/chttpd/src/chttpd_handlers.erl | 7 +
src/chttpd/src/chttpd_stats.erl | 9 +-
src/chttpd/src/chttpd_sup.erl | 10 ++
src/couch/src/couch_drv.erl | 2 +
src/couch/src/couch_flags_config.erl | 80 +++++------
src/couch/src/couch_httpd_auth.erl | 25 ++++
src/couch/src/couch_httpd_multipart.erl | 11 ++
src/couch/src/couch_httpd_vhost.erl | 6 +
src/couch/src/couch_proc_manager.erl | 1 +
src/couch/src/couch_sup.erl | 34 ++++-
.../src/couch_expiring_cache_fdb.erl | 2 +
.../src/couch_expiring_cache_server.erl | 5 +
src/couch_jobs/src/couch_jobs_activity_monitor.erl | 11 ++
src/couch_jobs/src/couch_jobs_notifier.erl | 5 +
src/couch_jobs/src/couch_jobs_server.erl | 11 ++
src/couch_js/src/couch_js_native_process.erl | 40 +++++-
src/couch_js/src/couch_js_os_process.erl | 64 +++++++++
src/couch_js/src/couch_js_proc_manager.erl | 8 ++
src/couch_js/src/couch_js_query_servers.erl | 7 +
src/couch_replicator/src/couch_replicator.erl | 9 ++
.../src/couch_replicator_api_wrap.erl | 21 +++
.../src/couch_replicator_auth_session.erl | 13 ++
.../src/couch_replicator_changes_reader.erl | 23 ++++
.../src/couch_replicator_connection.erl | 8 ++
src/couch_replicator/src/couch_replicator_docs.erl | 25 +++-
.../src/couch_replicator_httpc.erl | 29 ++++
src/couch_replicator/src/couch_replicator_job.erl | 151 ++++++++++++++++++++-
.../src/couch_replicator_job_server.erl | 33 +++++
.../src/couch_replicator_parse.erl | 27 ++++
.../src/couch_replicator_worker.erl | 94 ++++++++++++-
src/couch_views/src/couch_views_indexer.erl | 17 +++
src/couch_views/src/couch_views_server.erl | 5 +
src/couch_views/src/couch_views_sup.erl | 2 +
src/couch_views/src/couch_views_updater.erl | 15 ++
src/couch_views/src/couch_views_util.erl | 7 +
src/ctrace/src/ctrace.erl | 1 +
src/ctrace/src/ctrace_config.erl | 3 +
src/ctrace/test/ctrace_config_test.erl | 3 +
src/fabric/src/fabric2_db.erl | 2 +
src/fabric/src/fabric2_db_expiration.erl | 15 +-
src/fabric/src/fabric2_index.erl | 15 ++
src/fabric/src/fabric2_server.erl | 35 +++++
src/fabric/src/fabric2_users_db.erl | 8 ++
src/mango/src/mango_cursor_view.erl | 2 +
src/mango/src/mango_idx_view.erl | 7 +
51 files changed, 959 insertions(+), 56 deletions(-)
diff --git a/src/aegis/src/aegis_server.erl b/src/aegis/src/aegis_server.erl
index 15fea4c..92ba7e8 100644
--- a/src/aegis/src/aegis_server.erl
+++ b/src/aegis/src/aegis_server.erl
@@ -18,6 +18,7 @@
-include("aegis.hrl").
+-include_lib("kernel/include/logger.hrl").
%% aegis_server API
@@ -94,6 +95,7 @@ encrypt(#{} = Db, Key, Value) when is_binary(Key), is_binary(Value) ->
CipherText when is_binary(CipherText) ->
CipherText;
{error, {_Tag, {_C_FileName,_LineNumber}, _Desc} = Reason} ->
+ ?LOG_ERROR(#{what => encrypt_failure, details => Reason}),
couch_log:error("aegis encryption failure: ~p ", [Reason]),
erlang:error(decryption_failed);
{error, Reason} ->
@@ -119,6 +121,7 @@ decrypt(#{} = Db, Key, Value) when is_binary(Key), is_binary(Value) ->
PlainText when is_binary(PlainText) ->
PlainText;
{error, {_Tag, {_C_FileName,_LineNumber}, _Desc} = Reason} ->
+ ?LOG_ERROR(#{what => decrypt_failure, details => Reason}),
couch_log:error("aegis decryption failure: ~p ", [Reason]),
erlang:error(decryption_failed);
{error, Reason} ->
diff --git a/src/chttpd/include/chttpd.hrl b/src/chttpd/include/chttpd.hrl
index a7f9aaa..42263d9 100644
--- a/src/chttpd/include/chttpd.hrl
+++ b/src/chttpd/include/chttpd.hrl
@@ -10,6 +10,7 @@
% License for the specific language governing permissions and limitations under
% the License.
+-include_lib("kernel/include/logger.hrl").
-record(httpd_resp, {
end_ts,
diff --git a/src/chttpd/src/chttpd.erl b/src/chttpd/src/chttpd.erl
index 6741ca3..5d10d7d 100644
--- a/src/chttpd/src/chttpd.erl
+++ b/src/chttpd/src/chttpd.erl
@@ -16,6 +16,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("chttpd/include/chttpd.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([start_link/0, start_link/1, start_link/2,
stop/0, handle_request/1, handle_request_int/1,
@@ -206,7 +207,13 @@ handle_request_int(MochiReq) ->
true ->
couch_log:notice("MethodOverride: ~s (real method was ~s)", [MethodOverride, Method1]),
case Method1 of
- 'POST' -> couch_util:to_existing_atom(MethodOverride);
+ 'POST' ->
+ ?LOG_NOTICE(#{
+ what => http_method_override,
+ result => ok,
+ new_method => MethodOverride
+ }),
+ couch_util:to_existing_atom(MethodOverride);
_ ->
% Ignore X-HTTP-Method-Override when the original verb isn't POST.
% I'd like to send a 406 error to the client, but that'd require a nasty refactor.
@@ -268,6 +275,11 @@ handle_request_int(MochiReq) ->
span_ok(HttpResp),
{ok, Resp};
#httpd_resp{status = aborted, reason = Reason} ->
+ ?LOG_ERROR(#{
+ what => abnormal_response_termation,
+ id => get(nonce),
+ details => Reason
+ }),
couch_log:error("Response abnormally terminated: ~p", [Reason]),
exit(normal)
end.
@@ -348,6 +360,14 @@ catch_error(HttpReq, exit, {mochiweb_recv_error, E}, _Stack) ->
peer = Peer,
original_method = Method
} = HttpReq,
+ ?LOG_NOTICE(#{
+ what => mochiweb_recv_error,
+ id => get(nonce),
+ peer => Peer,
+ method => Method,
+ path => MochiReq:get(raw_path),
+ details => E
+ }),
couch_log:notice("mochiweb_recv_error for ~s - ~p ~s - ~p", [
Peer,
Method,
@@ -413,9 +433,24 @@ maybe_log(#httpd{} = HttpReq, #httpd_resp{should_log = true} = HttpResp) ->
User = get_user(HttpReq),
Host = MochiReq:get_header_value("Host"),
RawUri = MochiReq:get(raw_path),
- RequestTime = timer:now_diff(EndTime, BeginTime) / 1000,
+ RequestTime = round(timer:now_diff(EndTime, BeginTime) / 1000),
+ % Wish List
+ % - client port
+ % - timers: connection, request, time to first byte, ...
+ % - response size
+ %
+ ?LOG_NOTICE(#{
+ method => Method,
+ path => RawUri,
+ code => Code,
+ id => get(nonce),
+ user => User,
+ % req_size => MochiReq:get(body_length),
+ src => #{ip4 => Peer},
+ duration => RequestTime
+ }, #{domain => [chttpd_access_log]}),
couch_log:notice("~s ~s ~s ~s ~s ~B ~p ~B", [Host, Peer, User,
- Method, RawUri, Code, Status, round(RequestTime)]);
+ Method, RawUri, Code, Status, RequestTime]);
maybe_log(_HttpReq, #httpd_resp{should_log = false}) ->
ok.
@@ -1246,6 +1281,14 @@ maybe_decompress(Httpd, Body) ->
log_error_with_stack_trace({bad_request, _, _}) ->
ok;
log_error_with_stack_trace({Error, Reason, Stack}) ->
+ ?LOG_ERROR(#{
+ what => request_failure,
+ id => get(nonce),
+ error => Error,
+ reason => Reason,
+ hash => stack_hash(Stack),
+ stacktrace => Stack
+ }),
EFmt = if is_binary(Error) -> "~s"; true -> "~w" end,
RFmt = if is_binary(Reason) -> "~s"; true -> "~w" end,
Fmt = "req_err(~w) " ++ EFmt ++ " : " ++ RFmt ++ "~n ~p",
@@ -1396,8 +1439,13 @@ get_action(#httpd{} = Req) ->
try
chttpd_handlers:handler_info(Req)
catch Tag:Error ->
+ ?LOG_ERROR(#{
+ what => tracing_configuration_failure,
+ tag => Tag,
+ details => Error
+ }),
couch_log:error("Cannot set tracing action ~p:~p", [Tag, Error]),
- {undefind, #{}}
+ {undefined, #{}}
end.
span_ok(#httpd_resp{code = Code}) ->
diff --git a/src/chttpd/src/chttpd_auth_cache.erl b/src/chttpd/src/chttpd_auth_cache.erl
index c5a56bd..88ffb7a 100644
--- a/src/chttpd/src/chttpd_auth_cache.erl
+++ b/src/chttpd/src/chttpd_auth_cache.erl
@@ -22,6 +22,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch/include/couch_js_functions.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(CACHE, chttpd_auth_cache_lru).
-define(RELISTEN_DELAY, 5000).
@@ -74,6 +75,7 @@ get_from_cache(UserName) ->
try ets_lru:lookup_d(?CACHE, UserName) of
{ok, Props} ->
couch_stats:increment_counter([couchdb, auth_cache_hits]),
+ ?LOG_DEBUG(#{what => cache_hit, user => UserName}),
couch_log:debug("cache hit for ~s", [UserName]),
Props;
_ ->
@@ -96,6 +98,7 @@ maybe_increment_auth_cache_miss(UserName) ->
case lists:keymember(?b2l(UserName), 1, Admins) of
false ->
couch_stats:increment_counter([couchdb, auth_cache_misses]),
+ ?LOG_DEBUG(#{what => cache_miss, user => UserName}),
couch_log:debug("cache miss for ~s", [UserName]);
_True ->
ok
@@ -137,9 +140,18 @@ handle_info({'DOWN', _, _, Pid, Reason}, #state{changes_pid=Pid} = State) ->
{seq, EndSeq} ->
EndSeq;
{database_does_not_exist, _} ->
+ ?LOG_NOTICE(#{
+ what => changes_listener_died,
+ reason => database_does_not_exist,
+ details => "create the _users database to silence this notice"
+ }),
couch_log:notice("~p changes listener died because the _users database does not exist. Create the database to silence this notice.", [?MODULE]),
0;
_ ->
+ ?LOG_NOTICE(#{
+ what => changes_listener_died,
+ reason => Reason
+ }),
couch_log:notice("~p changes listener died ~r", [?MODULE, Reason]),
0
end,
@@ -192,6 +204,7 @@ changes_callback({change, {Change}}, _) ->
ok;
DocId ->
UserName = username(DocId),
+ ?LOG_DEBUG(#{what => invalidate_cache, user => UserName}),
couch_log:debug("Invalidating cached credentials for ~s", [UserName]),
ets_lru:remove(?CACHE, UserName)
end,
@@ -221,6 +234,10 @@ load_user_from_db(UserName) ->
{Props} = couch_doc:to_json_obj(Doc, []),
Props;
_Else ->
+ ?LOG_DEBUG(#{
+ what => missing_user_document,
+ user => UserName
+ }),
couch_log:debug("no record of user ~s", [UserName]),
nil
catch error:database_does_not_exist ->
@@ -267,6 +284,12 @@ ensure_auth_ddoc_exists(Db, DDocId) ->
update_doc_ignoring_conflict(Db, NewDoc)
end;
{error, Reason} ->
+ ?LOG_NOTICE(#{
+ what => ensure_auth_ddoc_exists_failure,
+ db => dbname(),
+ docid => DDocId,
+ details => Reason
+ }),
couch_log:notice("Failed to ensure auth ddoc ~s/~s exists for reason: ~p", [dbname(), DDocId, Reason]),
ok
end,
diff --git a/src/chttpd/src/chttpd_cors.erl b/src/chttpd/src/chttpd_cors.erl
index a8dd348..ba13233 100644
--- a/src/chttpd/src/chttpd_cors.erl
+++ b/src/chttpd/src/chttpd_cors.erl
@@ -27,6 +27,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("chttpd/include/chttpd_cors.hrl").
+-include_lib("kernel/include/logger.hrl").
%% http://www.w3.org/TR/cors/#resource-preflight-requests
@@ -51,6 +52,12 @@ maybe_handle_preflight_request(#httpd{}=Req, Config) ->
not_preflight ->
not_preflight;
UnknownError ->
+ ?LOG_ERROR(#{
+ what => preflight_request_error,
+ origin => get_origin(Req),
+ accepted_origins => get_accepted_origins(Req, Config),
+ details => UnknownError
+ }),
couch_log:error(
"Unknown response of chttpd_cors:preflight_request(~p): ~p",
[Req, UnknownError]
diff --git a/src/chttpd/src/chttpd_db.erl b/src/chttpd/src/chttpd_db.erl
index 8f08c7f..4a7b631 100644
--- a/src/chttpd/src/chttpd_db.erl
+++ b/src/chttpd/src/chttpd_db.erl
@@ -16,6 +16,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_views/include/couch_views.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([handle_request/1, handle_compact_req/2, handle_design_req/2,
db_req/2, couch_doc_open/4,handle_changes_req/2,
@@ -360,6 +361,12 @@ db_req(#httpd{method='POST', path_parts=[DbName]}=Req, Db) ->
chttpd_stats:incr_writes(),
ok;
Error ->
+ ?LOG_DEBUG(#{
+ what => async_update_error,
+ db => DbName,
+ docid => DocId,
+ details => Error
+ }),
couch_log:debug("Batch doc error (~s): ~p",[DocId, Error])
end
end),
@@ -1108,6 +1115,12 @@ db_doc_req(#httpd{method='PUT'}=Req, Db, DocId) ->
chttpd_stats:incr_writes(),
ok;
Error ->
+ ?LOG_NOTICE(#{
+ what => async_update_error,
+ db => DbName,
+ docid => DocId,
+ details => Error
+ }),
couch_log:notice("Batch doc error (~s): ~p",[DocId, Error])
end
end),
@@ -1944,6 +1957,10 @@ monitor_attachments(Atts) when is_list(Atts) ->
stub ->
Monitors;
Else ->
+ ?LOG_ERROR(#{
+ what => malformed_attachment_data,
+ attachment => Att
+ }),
couch_log:error("~p from couch_att:fetch(data, ~p)", [Else, Att]),
Monitors
end
diff --git a/src/chttpd/src/chttpd_handlers.erl b/src/chttpd/src/chttpd_handlers.erl
index ce47820..d4b7a7d 100644
--- a/src/chttpd/src/chttpd_handlers.erl
+++ b/src/chttpd/src/chttpd_handlers.erl
@@ -22,6 +22,7 @@
-define(SERVICE_ID, chttpd_handlers).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
%% ------------------------------------------------------------------
%% API Function Definitions
@@ -45,6 +46,12 @@ handler_info(HttpReq) ->
try
select(collect(handler_info, [Method, PathParts, HttpReq]), Default)
catch Type:Reason:Stack ->
+ ?LOG_ERROR(#{
+ id => get(nonce),
+ result => Type,
+ details => Reason,
+ stack => Stack
+ }),
couch_log:error("~s :: handler_info failure for ~p : ~p:~p :: ~p", [
?MODULE,
get(nonce),
diff --git a/src/chttpd/src/chttpd_stats.erl b/src/chttpd/src/chttpd_stats.erl
index fa2036e..1862278 100644
--- a/src/chttpd/src/chttpd_stats.erl
+++ b/src/chttpd/src/chttpd_stats.erl
@@ -12,6 +12,7 @@
-module(chttpd_stats).
+-include_lib("kernel/include/logger.hrl").
-export([
init/1,
@@ -62,12 +63,18 @@ report(HttpResp) ->
ok
end
catch T:R:S ->
+ ?LOG_ERROR(#{
+ what => stats_report_failure,
+ tag => T,
+ details => R,
+ stacktrace => S
+ }),
Fmt = "Failed to report chttpd request stats: ~p:~p ~p",
couch_log:error(Fmt, [T, R, S])
end.
-report(HttpResp, #st{reporter = undefined}) ->
+report(_HttpResp, #st{reporter = undefined}) ->
ok;
report(HttpResp, #st{reporter = Reporter} = St) ->
diff --git a/src/chttpd/src/chttpd_sup.erl b/src/chttpd/src/chttpd_sup.erl
index 8b51e6c..44eeb7a 100644
--- a/src/chttpd/src/chttpd_sup.erl
+++ b/src/chttpd/src/chttpd_sup.erl
@@ -22,6 +22,8 @@
-export([handle_config_change/5, handle_config_terminate/3]).
+-include_lib("kernel/include/logger.hrl").
+
%% Helper macro for declaring children of supervisor
-define(CHILD(I, Type), {I, {I, start_link, []}, permanent, 100, Type, [I]}).
@@ -33,6 +35,7 @@ start_link() ->
supervisor:start_link({local,?MODULE}, ?MODULE, Arg).
init(disabled) ->
+ ?LOG_NOTICE(#{what => http_api_disabled}),
couch_log:notice("~p : api_frontend disabled", [?MODULE]),
{ok, {{one_for_one, 3, 10}, []}};
@@ -99,6 +102,13 @@ append_if_set({Key, Value}, Opts) when Value > 0 ->
append_if_set({_Key, 0}, Opts) ->
Opts;
append_if_set({Key, Value}, Opts) ->
+ ?LOG_ERROR(#{
+ what => invalid_config_setting,
+ section => chttpd_auth_cache,
+ key => Key,
+ value => Value,
+ details => "value must be a positive integer"
+ }),
couch_log:error(
"The value for `~s` should be string convertable "
"to integer which is >= 0 (got `~p`)", [Key, Value]),
diff --git a/src/couch/src/couch_drv.erl b/src/couch/src/couch_drv.erl
index f2ff2ac..002facd 100644
--- a/src/couch/src/couch_drv.erl
+++ b/src/couch/src/couch_drv.erl
@@ -19,6 +19,7 @@
-export([start_link/0]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
start_link() ->
gen_server:start_link({local, ?MODULE}, ?MODULE, [], []).
@@ -29,6 +30,7 @@ init([]) ->
ok ->
{ok, nil};
{error, already_loaded} ->
+ ?LOG_INFO(#{what => reload_couch_icu_driver}),
couch_log:info("~p reloading couch_icu_driver", [?MODULE]),
ok = erl_ddll:reload(LibDir, "couch_icu_driver"),
{ok, nil};
diff --git a/src/couch/src/couch_flags_config.erl b/src/couch/src/couch_flags_config.erl
index 104a482..883fe38 100644
--- a/src/couch/src/couch_flags_config.erl
+++ b/src/couch/src/couch_flags_config.erl
@@ -13,6 +13,8 @@
% This module implements {flags, config} data provider
-module(couch_flags_config).
+-include_lib("kernel/include/logger.hrl").
+
-export([
enable/2,
data/0,
@@ -80,50 +82,53 @@ data(Config) ->
-spec parse_rules([{Key :: string(), Value :: string()}]) -> [rule()].
parse_rules(Config) ->
- lists:filtermap(fun({K, V}) ->
- case parse_rule(K, V) of
- {error, {Format, Args}} ->
- couch_log:error(Format, Args),
- false;
- Rule ->
- {true, Rule}
- end
- end, Config).
-
--spec parse_rule(Key :: string(), Value :: string()) ->
- rule()
- | {error, Reason :: term()}.
-
-parse_rule(Key, "true") ->
- parse_flags(binary:split(list_to_binary(Key), <<"||">>), true);
-parse_rule(Key, "false") ->
- parse_flags(binary:split(list_to_binary(Key), <<"||">>), false);
+ lists:filtermap(fun({K, V}) -> parse_rule(K, V) end, Config).
+
+-spec parse_rule(Key :: string(), Value :: string()) -> {true, rule()} | false.
+
+parse_rule(Key, Value) when Value =:= "true" orelse Value =:= "false" ->
+ case binary:split(list_to_binary(Key), <<"||">>) of
+ [FlagsBin, PatternBin] ->
+ parse_flags([FlagsBin, PatternBin], list_to_atom(Value));
+ _ ->
+ ?LOG_ERROR(#{
+ what => invalid_flag_setting,
+ key => Key,
+ value => Value,
+ details => "key must be in the form of `[flags]||pattern`"
+ }),
+ false
+ end;
parse_rule(Key, Value) ->
- Reason = {
- "Expected value for the `~p` either `true` or `false`, (got ~p)",
- [Key, Value]
- },
- {error, Reason}.
+ ?LOG_ERROR(#{
+ what => invalid_flag_setting,
+ key => Key,
+ value => Value,
+ details => "value must be a boolean"
+ }),
+ false.
--spec parse_flags([binary()], Value :: boolean()) ->
- rule() | {error, Reason :: term()}.
+-spec parse_flags([binary()], Value :: boolean()) -> {true, rule()} | false.
parse_flags([FlagsBin, PatternBin], Value) ->
case {parse_flags_term(FlagsBin), Value} of
- {{error, _} = Error, _} ->
- Error;
+ {{error, Errors}, _} ->
+ lists:foreach(fun(Error) ->
+ ?LOG_ERROR(#{
+ what => invalid_flag_setting,
+ flags => FlagsBin,
+ error => Error
+ })
+ end, Errors),
+ false;
{Flags, true} ->
- {parse_pattern(PatternBin), Flags, []};
+ {true, {parse_pattern(PatternBin), Flags, []}};
{Flags, false} ->
- {parse_pattern(PatternBin), [], Flags}
- end;
-parse_flags(_Tokens, _) ->
- couch_log:error(
- "Key should be in the form of `[flags]||pattern` (got ~s)", []),
- false.
+ {true, {parse_pattern(PatternBin), [], Flags}}
+ end.
-spec parse_flags_term(Flags :: binary()) ->
- [flag_id()] | {error, Reason :: term()}.
+ [flag_id()] | {error, Failures :: [term()]}.
parse_flags_term(FlagsBin) ->
{Flags, Errors} = lists:splitwith(fun erlang:is_atom/1,
@@ -132,10 +137,7 @@ parse_flags_term(FlagsBin) ->
[] ->
lists:usort(Flags);
_ ->
- {error, {
- "Cannot parse list of tags: ~n~p",
- Errors
- }}
+ {error, Errors}
end.
split_by_comma(Binary) ->
diff --git a/src/couch/src/couch_httpd_auth.erl b/src/couch/src/couch_httpd_auth.erl
index 7d728e6..b740220 100644
--- a/src/couch/src/couch_httpd_auth.erl
+++ b/src/couch/src/couch_httpd_auth.erl
@@ -15,6 +15,7 @@
-compile(tuple_calls).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([party_mode_handler/1]).
@@ -212,6 +213,12 @@ get_configured_claims() ->
Re = "((?<key1>[a-z]+)|{(?<key2>[a-z]+)\s*,\s*\"(?<val>[^\"]+)\"})",
case re:run(Claims, Re, [global, {capture, [key1, key2, val], binary}]) of
nomatch when Claims /= "" ->
+ ?LOG_ERROR(#{
+ what => invalid_config_setting,
+ section => jwt_auth,
+ key => required_claims,
+ value => Claims
+ }),
couch_log:error("[jwt_auth] required_claims is set to an invalid value.", []),
throw({misconfigured_server, <<"JWT is not configured correctly">>});
nomatch ->
@@ -246,6 +253,7 @@ cookie_authentication_handler(#httpd{mochi_req=MochiReq}=Req, AuthModule) ->
CurrentTime = make_cookie_time(),
case config:get("couch_httpd_auth", "secret", undefined) of
undefined ->
+ ?LOG_DEBUG(#{what => cookie_auth_secret_undefined}),
couch_log:debug("cookie auth secret is not set",[]),
Req;
SecretStr ->
@@ -265,6 +273,10 @@ cookie_authentication_handler(#httpd{mochi_req=MochiReq}=Req, AuthModule) ->
case couch_passwords:verify(ExpectedHash, Hash) of
true ->
TimeLeft = TimeStamp + Timeout - CurrentTime,
+ ?LOG_DEBUG(#{
+ what => successful_cookie_auth,
+ username => User
+ }),
couch_log:debug("Successful cookie auth as: ~p",
[User]),
Req#httpd{user_ctx=#user_ctx{
@@ -338,6 +350,7 @@ handle_session_req(#httpd{method='POST', mochi_req=MochiReq}=Req, AuthModule) ->
end,
UserName = ?l2b(extract_username(Form)),
Password = ?l2b(couch_util:get_value("password", Form, "")),
+ ?LOG_DEBUG(#{what => login_attempt, user => UserName}),
couch_log:debug("Attempt Login: ~s",[UserName]),
{ok, UserProps, _AuthCtx} = case AuthModule:get_user_creds(Req, UserName) of
nil -> {ok, [], nil};
@@ -501,6 +514,13 @@ same_site() ->
"lax" -> [{same_site, lax}];
"strict" -> [{same_site, strict}];
_ ->
+ ?LOG_ERROR(#{
+ what => invalid_config_setting,
+ section => couch_httpd_auth,
+ key => same_site,
+ value => SameSite,
+ details => "value must be one of `none`, `lax`, `strict`"
+ }),
couch_log:error("invalid config value couch_httpd_auth.same_site: ~p ",[SameSite]),
[]
end.
@@ -561,5 +581,10 @@ integer_to_binary(Int, Len) when is_integer(Int), is_integer(Len) ->
authentication_warning(#httpd{mochi_req = Req}, User) ->
Peer = Req:get(peer),
+ ?LOG_WARNING(#{
+ what => authentication_failure,
+ user => User,
+ peer => Peer
+ }),
couch_log:warning("~p: Authentication failed for user ~s from ~s",
[?MODULE, User, Peer]).
diff --git a/src/couch/src/couch_httpd_multipart.erl b/src/couch/src/couch_httpd_multipart.erl
index 33795a3..7e6e7d6 100644
--- a/src/couch/src/couch_httpd_multipart.erl
+++ b/src/couch/src/couch_httpd_multipart.erl
@@ -22,6 +22,7 @@
]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
decode_multipart_stream(ContentType, DataFun, Ref) ->
Parent = self(),
@@ -45,10 +46,20 @@ decode_multipart_stream(ContentType, DataFun, Ref) ->
{'DOWN', ParserRef, _, _, normal} ->
ok;
{'DOWN', ParserRef, process, Parser, {{nocatch, {Error, Msg}}, _}} ->
+ ?LOG_ERROR(#{
+ what => multipart_streamer_failure,
+ ref => ParserRef,
+ details => Msg
+ }),
couch_log:error("Multipart streamer ~p died with reason ~p",
[ParserRef, Msg]),
throw({Error, Msg});
{'DOWN', ParserRef, _, _, Reason} ->
+ ?LOG_ERROR(#{
+ what => multipart_streamer_failure,
+ ref => ParserRef,
+ details => Reason
+ }),
couch_log:error("Multipart streamer ~p died with reason ~p",
[ParserRef, Reason]),
throw({error, Reason})
diff --git a/src/couch/src/couch_httpd_vhost.erl b/src/couch/src/couch_httpd_vhost.erl
index 574dba9..3d6b4da 100644
--- a/src/couch/src/couch_httpd_vhost.erl
+++ b/src/couch/src/couch_httpd_vhost.erl
@@ -27,6 +27,7 @@
-export([handle_config_change/5, handle_config_terminate/3]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(SEPARATOR, $\/).
-define(MATCH_ALL, {bind, '*'}).
@@ -146,6 +147,11 @@ redirect_to_vhost(MochiReq, VhostTarget) ->
Path = MochiReq:get(raw_path),
Target = append_path(VhostTarget, Path),
+ ?LOG_DEBUG(#{
+ what => vhost_redirect,
+ raw_path => Path,
+ target => Target
+ }),
couch_log:debug("Vhost Target: '~p'~n", [Target]),
Headers = mochiweb_headers:enter("x-couchdb-vhost-path", Path,
diff --git a/src/couch/src/couch_proc_manager.erl b/src/couch/src/couch_proc_manager.erl
index 3faef09..4627a9f 100644
--- a/src/couch/src/couch_proc_manager.erl
+++ b/src/couch/src/couch_proc_manager.erl
@@ -41,6 +41,7 @@
]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(PROCS, couch_proc_manager_procs).
-define(WAITERS, couch_proc_manager_waiters).
diff --git a/src/couch/src/couch_sup.erl b/src/couch/src/couch_sup.erl
index 6e7ef98..7a1afae 100644
--- a/src/couch/src/couch_sup.erl
+++ b/src/couch/src/couch_sup.erl
@@ -25,6 +25,7 @@
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
start_link() ->
@@ -93,6 +94,11 @@ assert_admins() ->
couch_log:info("Preflight check: Asserting Admin Account~n", []),
case {config:get("admins"), os:getenv("COUCHDB_TEST_ADMIN_PARTY_OVERRIDE")} of
{[], false} ->
+ ?LOG_INFO(#{
+ what => admin_account_missing,
+ details => "No admin account found, aborting startup. Please configure "
+ "an admin account in your local.ini file."
+ }),
couch_log:info("~n%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%~n"
++ " No Admin Account Found, aborting startup. ~n"
++ " Please configure an admin account in your local.ini file. ~n"
@@ -104,6 +110,11 @@ assert_admins() ->
end.
send_no_admin_account_error_message() ->
+ ?LOG_ERROR(#{
+ what => admin_account_missing,
+ details => "No admin account configured. Please configure an admin "
+ "account in your local.ini file and restart CouchDB."
+ }),
couch_log:error("No Admin Account configured."
++ " Please configure an Admin Account in your local.ini file and restart CouchDB.~n", []),
FiveMinutes = 5 * 1000 * 60,
@@ -118,21 +129,37 @@ maybe_launch_admin_annoyance_reporter() ->
notify_starting() ->
+ ?LOG_INFO(#{
+ what => starting_couchdb,
+ version => couch_server:get_version()
+ }),
couch_log:info("Apache CouchDB ~s is starting.~n", [
couch_server:get_version()
]).
notify_started() ->
+ ?LOG_INFO(#{
+ what => starting_couchdb_complete,
+ time_to_relax => true
+ }),
couch_log:info("Apache CouchDB has started. Time to relax.~n", []).
notify_error(Error) ->
+ ?LOG_ERROR(#{
+ what => error_on_startup,
+ details => Error
+ }),
couch_log:error("Error starting Apache CouchDB:~n~n ~p~n~n", [Error]).
notify_uris() ->
lists:foreach(fun(Uri) ->
+ ?LOG_INFO(#{
+ what => couchdb_listener_started,
+ uri => Uri
+ }),
couch_log:info("Apache CouchDB has started on ~s", [Uri])
end, get_uris()).
@@ -193,7 +220,12 @@ write_file(FileName, Contents) ->
ok ->
ok;
{error, Reason} ->
+ ?LOG_ERROR(#{
+ what => file_write_failure,
+ filename => FileName,
+ error => file:format_error(Reason)
+ }),
Args = [FileName, file:format_error(Reason)],
- couch_log:error("Failed ot write ~s :: ~s", Args),
+ couch_log:error("Failed to write ~s :: ~s", Args),
throw({error, Reason})
end.
diff --git a/src/couch_expiring_cache/src/couch_expiring_cache_fdb.erl b/src/couch_expiring_cache/src/couch_expiring_cache_fdb.erl
index fe37a7c..ebc97b9 100644
--- a/src/couch_expiring_cache/src/couch_expiring_cache_fdb.erl
+++ b/src/couch_expiring_cache/src/couch_expiring_cache_fdb.erl
@@ -27,6 +27,7 @@
-include_lib("fabric/include/fabric2.hrl").
-include_lib("couch_expiring_cache/include/couch_expiring_cache.hrl").
+-include_lib("kernel/include/logger.hrl").
% Data model
@@ -107,6 +108,7 @@ get_range_to(Name, EndTS, Limit) when Limit > 0 ->
fun(Tx, PK, _XK, Key, _ExpiresTS, Acc) ->
case get_val(Tx, PK) of
not_found ->
+ ?LOG_ERROR(#{what => missing_key, key => Key}),
couch_log:error("~p:entry missing Key: ~p", [?MODULE, Key]),
Acc;
Val ->
diff --git a/src/couch_expiring_cache/src/couch_expiring_cache_server.erl b/src/couch_expiring_cache/src/couch_expiring_cache_server.erl
index 74c432e..9c0c899 100644
--- a/src/couch_expiring_cache/src/couch_expiring_cache_server.erl
+++ b/src/couch_expiring_cache/src/couch_expiring_cache_server.erl
@@ -37,6 +37,7 @@
-include_lib("couch_expiring_cache/include/couch_expiring_cache.hrl").
+-include_lib("kernel/include/logger.hrl").
start_link(Name, Opts) when is_atom(Name) ->
@@ -96,6 +97,10 @@ handle_info(remove_expired, St) ->
handle_info({Ref, ready}, St) when is_reference(Ref) ->
% Prevent crashing server and application
+ ?LOG_ERROR(#{
+ what => spurious_future_ready,
+ ref => Ref
+ }),
LogMsg = "~p : spurious erlfdb future ready message ~p",
couch_log:error(LogMsg, [?MODULE, Ref]),
{noreply, St};
diff --git a/src/couch_jobs/src/couch_jobs_activity_monitor.erl b/src/couch_jobs/src/couch_jobs_activity_monitor.erl
index d5dfa41..ef1ce1e 100644
--- a/src/couch_jobs/src/couch_jobs_activity_monitor.erl
+++ b/src/couch_jobs/src/couch_jobs_activity_monitor.erl
@@ -30,6 +30,7 @@
-include("couch_jobs.hrl").
+-include_lib("kernel/include/logger.hrl").
-record(st, {
@@ -74,6 +75,12 @@ handle_info(check_activity, St) ->
catch
error:{erlfdb_error, Err} when ?ERLFDB_IS_RETRYABLE(Err) orelse
Err =:= ?ERLFDB_TRANSACTION_TIMED_OUT ->
+ ?LOG_ERROR(#{
+ what => erlfdb_error,
+ job_type => St#st.type,
+ error_code => Err,
+ details => "possible overload condition"
+ }),
LogMsg = "~p : type:~p got ~p error, possibly from overload",
couch_log:error(LogMsg, [?MODULE, St#st.type, Err]),
St
@@ -84,6 +91,10 @@ handle_info(check_activity, St) ->
handle_info({Ref, ready}, St) when is_reference(Ref) ->
% Don't crash out couch_jobs_server and the whole application would need to
% eventually do proper cleanup in erlfdb:wait timeout code.
+ ?LOG_ERROR(#{
+ what => spurious_future_ready,
+ ref => Ref
+ }),
LogMsg = "~p : spurious erlfdb future ready message ~p",
couch_log:error(LogMsg, [?MODULE, Ref]),
{noreply, St};
diff --git a/src/couch_jobs/src/couch_jobs_notifier.erl b/src/couch_jobs/src/couch_jobs_notifier.erl
index db5d5e0..fea7084 100644
--- a/src/couch_jobs/src/couch_jobs_notifier.erl
+++ b/src/couch_jobs/src/couch_jobs_notifier.erl
@@ -33,6 +33,7 @@
-include("couch_jobs.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(TYPE_MONITOR_HOLDOFF_DEFAULT, 50).
@@ -121,6 +122,10 @@ handle_info({type_updated, VS}, St) ->
handle_info({Ref, ready}, St) when is_reference(Ref) ->
% Don't crash out couch_jobs_server and the whole application would need to
% eventually do proper cleanup in erlfdb:wait timeout code.
+ ?LOG_ERROR(#{
+ what => spurious_future_ready,
+ ref => Ref
+ }),
LogMsg = "~p : spurious erlfdb future ready message ~p",
couch_log:error(LogMsg, [?MODULE, Ref]),
{noreply, St};
diff --git a/src/couch_jobs/src/couch_jobs_server.erl b/src/couch_jobs/src/couch_jobs_server.erl
index 2e03c7d..5f9def6 100644
--- a/src/couch_jobs/src/couch_jobs_server.erl
+++ b/src/couch_jobs/src/couch_jobs_server.erl
@@ -14,6 +14,7 @@
-behaviour(gen_server).
+-include_lib("kernel/include/logger.hrl").
-export([
start_link/0,
@@ -92,6 +93,11 @@ handle_info(check_types, St) ->
{noreply, St};
handle_info({'DOWN', _Ref, process, Pid, Reason}, St) ->
+ ?LOG_ERROR(#{
+ what => unknown_process_crash,
+ pid => Pid,
+ details => Reason
+ }),
LogMsg = "~p : process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{stop, {unexpected_process_exit, Pid, Reason}, St};
@@ -99,6 +105,10 @@ handle_info({'DOWN', _Ref, process, Pid, Reason}, St) ->
handle_info({Ref, ready}, St) when is_reference(Ref) ->
% Don't crash out couch_jobs_server and the whole application would need to
% eventually do proper cleanup in erlfdb:wait timeout code.
+ ?LOG_ERROR(#{
+ what => spurious_future_ready,
+ ref => Ref
+ }),
LogMsg = "~p : spurious erlfdb future ready message ~p",
couch_log:error(LogMsg, [?MODULE, Ref]),
{noreply, St};
@@ -171,6 +181,7 @@ fdb_types() ->
end)
catch
error:{timeout, _} ->
+ ?LOG_WARNING(#{what => fdb_connection_timeout}),
couch_log:warning("~p : Timed out connecting to FDB", [?MODULE]),
[]
end.
diff --git a/src/couch_js/src/couch_js_native_process.erl b/src/couch_js/src/couch_js_native_process.erl
index d5ed3f9..8add3d5 100644
--- a/src/couch_js/src/couch_js_native_process.erl
+++ b/src/couch_js/src/couch_js_native_process.erl
@@ -56,6 +56,7 @@
}).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
start_link() ->
gen_server:start_link(?MODULE, [], []).
@@ -80,6 +81,11 @@ handle_call({set_timeout, TimeOut}, _From, State) ->
{reply, ok, State#evstate{timeout=TimeOut}, State#evstate.idle};
handle_call({prompt, Data}, _From, State) ->
+ ?LOG_DEBUG(#{
+ what => prompt,
+ in => native_process,
+ msg => ?JSON_ENCODE(Data)
+ }),
couch_log:debug("Prompt native qs: ~s",[?JSON_ENCODE(Data)]),
{NewState, Resp} = try run(State, to_binary(Data)) of
{S, R} -> {S, R}
@@ -211,6 +217,11 @@ run(#evstate{ddocs=DDocs}=State, [<<"ddoc">>, DDocId | Rest]) ->
DDoc = load_ddoc(DDocs, DDocId),
ddoc(State, DDoc, Rest);
run(_, Unknown) ->
+ ?LOG_ERROR(#{
+ what => unknown_command,
+ in => native_process,
+ cmd => Unknown
+ }),
couch_log:error("Native Process: Unknown command: ~p~n", [Unknown]),
throw({error, unknown_command}).
@@ -237,7 +248,13 @@ ddoc(State, {_, Fun}, [<<"filters">>|_], [Docs, Req]) ->
case catch Fun(Doc, Req) of
true -> true;
false -> false;
- {'EXIT', Error} -> couch_log:error("~p", [Error])
+ {'EXIT', Error} ->
+ ?LOG_ERROR(#{
+ what => filter_fun_crash,
+ in => native_process,
+ details => Error
+ }),
+ couch_log:error("~p", [Error])
end
end,
Resp = lists:map(FilterFunWrapper, Docs),
@@ -249,7 +266,13 @@ ddoc(State, {_, Fun}, [<<"views">>|_], [Docs]) ->
ok -> false;
false -> false;
[_|_] -> true;
- {'EXIT', Error} -> couch_log:error("~p", [Error])
+ {'EXIT', Error} ->
+ ?LOG_ERROR(#{
+ what => view_fun_crash,
+ in => native_process,
+ details => Error
+ }),
+ couch_log:error("~p", [Error])
end
end,
Resp = lists:map(MapFunWrapper, Docs),
@@ -318,6 +341,12 @@ bindings(State, Sig, DDoc) ->
Self = self(),
Log = fun(Msg) ->
+ ?LOG_INFO(#{
+ what => user_defined_log,
+ in => native_process,
+ signature => Sig,
+ msg => Msg
+ }),
couch_log:info(Msg, [])
end,
@@ -393,6 +422,13 @@ makefun(_State, Source, BindFuns) when is_list(BindFuns) ->
{ok, [ParsedForm]} ->
ParsedForm;
{error, {LineNum, _Mod, [Mesg, Params]}}=Error ->
+ ?LOG_ERROR(#{
+ what => syntax_error,
+ in => native_process,
+ line => LineNum,
+ details => Mesg,
+ parameters => Params
+ }),
couch_log:error("Syntax error on line: ~p~n~s~p~n",
[LineNum, Mesg, Params]),
throw(Error)
diff --git a/src/couch_js/src/couch_js_os_process.erl b/src/couch_js/src/couch_js_os_process.erl
index 883bc8f..181ca09 100644
--- a/src/couch_js/src/couch_js_os_process.erl
+++ b/src/couch_js/src/couch_js_os_process.erl
@@ -20,6 +20,7 @@
-export([init/1, terminate/2, handle_call/3, handle_cast/2, handle_info/2, code_change/3]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(PORT_OPTIONS, [stream, {line, 4096}, binary, exit_status, hide]).
@@ -55,6 +56,12 @@ prompt(Pid, Data) ->
{ok, Result} ->
Result;
Error ->
+ ?LOG_ERROR(#{
+ what => communication_error,
+ in => os_process,
+ pid => Pid,
+ details => Error
+ }),
couch_log:error("OS Process Error ~p :: ~p",[Pid,Error]),
throw(Error)
end.
@@ -95,12 +102,24 @@ readline(#os_proc{port = Port} = OsProc, Acc) ->
% Standard JSON functions
writejson(OsProc, Data) when is_record(OsProc, os_proc) ->
JsonData = ?JSON_ENCODE(Data),
+ ?LOG_DEBUG(#{
+ what => writeline,
+ in => os_process,
+ port => OsProc#os_proc.port,
+ data => JsonData
+ }),
couch_log:debug("OS Process ~p Input :: ~s",
[OsProc#os_proc.port, JsonData]),
true = writeline(OsProc, JsonData).
readjson(OsProc) when is_record(OsProc, os_proc) ->
Line = iolist_to_binary(readline(OsProc)),
+ ?LOG_DEBUG(#{
+ what => readline,
+ in => os_process,
+ port => OsProc#os_proc.port,
+ data => Line
+ }),
couch_log:debug("OS Process ~p Output :: ~s", [OsProc#os_proc.port, Line]),
try
% Don't actually parse the whole JSON. Just try to see if it's
@@ -115,12 +134,24 @@ readjson(OsProc) when is_record(OsProc, os_proc) ->
case ?JSON_DECODE(Line) of
[<<"log">>, Msg] when is_binary(Msg) ->
% we got a message to log. Log it and continue
+ ?LOG_INFO(#{
+ what => user_defined_log,
+ in => os_process,
+ port => OsProc#os_proc.port,
+ msg => Msg
+ }),
couch_log:info("OS Process ~p Log :: ~s",
[OsProc#os_proc.port, Msg]),
readjson(OsProc);
[<<"error">>, Id, Reason] ->
throw({error, {couch_util:to_existing_atom(Id),Reason}});
[<<"fatal">>, Id, Reason] ->
+ ?LOG_INFO(#{
+ what => fatal_error,
+ in => os_process,
+ port => OsProc#os_proc.port,
+ details => Reason
+ }),
couch_log:info("OS Process ~p Fatal Error :: ~s ~p",
[OsProc#os_proc.port, Id, Reason]),
throw({couch_util:to_existing_atom(Id),Reason});
@@ -163,6 +194,11 @@ init([Command, Options, PortOptions]) ->
},
KillCmd = iolist_to_binary(readline(BaseProc)),
Pid = self(),
+ ?LOG_DEBUG(#{
+ what => init,
+ in => os_process,
+ port => BaseProc#os_proc.port
+ }),
couch_log:debug("OS Process Start :: ~p", [BaseProc#os_proc.port]),
spawn(fun() ->
% this ensure the real os process is killed when this process dies.
@@ -216,6 +252,12 @@ handle_cast({send, Data}, #os_proc{writer=Writer, idle=Idle}=OsProc) ->
{noreply, OsProc, Idle}
catch
throw:OsError ->
+ ?LOG_INFO(#{
+ what => write_failure,
+ in => os_process,
+ details => OsError,
+ data => Data
+ }),
couch_log:error("Failed sending data: ~p -> ~p", [Data, OsError]),
{stop, normal, OsProc}
end;
@@ -225,6 +267,11 @@ handle_cast(garbage_collect, #os_proc{idle=Idle}=OsProc) ->
handle_cast(stop, OsProc) ->
{stop, normal, OsProc};
handle_cast(Msg, #os_proc{idle=Idle}=OsProc) ->
+ ?LOG_DEBUG(#{
+ what => unknown_message,
+ in => os_process,
+ data => Msg
+ }),
couch_log:debug("OS Proc: Unknown cast: ~p", [Msg]),
{noreply, OsProc, Idle}.
@@ -233,12 +280,29 @@ handle_info(timeout, #os_proc{idle=Idle}=OsProc) ->
erlang:garbage_collect(),
{noreply, OsProc, Idle};
handle_info({Port, {exit_status, 0}}, #os_proc{port=Port}=OsProc) ->
+ ?LOG_INFO(#{
+ what => normal_termination,
+ in => os_process,
+ port => Port
+ }),
couch_log:info("OS Process terminated normally", []),
{stop, normal, OsProc};
handle_info({Port, {exit_status, Status}}, #os_proc{port=Port}=OsProc) ->
+ ?LOG_ERROR(#{
+ what => abnormal_termination,
+ in => os_process,
+ port => Port,
+ exit_status => Status
+ }),
couch_log:error("OS Process died with status: ~p", [Status]),
{stop, {exit_status, Status}, OsProc};
handle_info(Msg, #os_proc{idle=Idle}=OsProc) ->
+ ?LOG_DEBUG(#{
+ what => unexpected_message,
+ in => os_process,
+ port => OsProc#os_proc.port,
+ msg => Msg
+ }),
couch_log:debug("OS Proc: Unknown info: ~p", [Msg]),
{noreply, OsProc, Idle}.
diff --git a/src/couch_js/src/couch_js_proc_manager.erl b/src/couch_js/src/couch_js_proc_manager.erl
index d9c3efc..0f55ced 100644
--- a/src/couch_js/src/couch_js_proc_manager.erl
+++ b/src/couch_js/src/couch_js_proc_manager.erl
@@ -40,6 +40,7 @@
]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(PROCS, couch_js_proc_manager_procs).
-define(WAITERS, couch_js_proc_manager_waiters).
@@ -197,6 +198,7 @@ handle_cast({os_proc_idle, Pid}, #state{counts=Counts}=State) ->
[#proc_int{client=undefined, lang=Lang}=Proc] ->
case dict:find(Lang, Counts) of
{ok, Count} when Count >= State#state.soft_limit ->
+ ?LOG_INFO(#{what => close_idle_os_process, pid => Pid}),
couch_log:info("Closing idle OS Process: ~p", [Pid]),
remove_proc(State, Proc);
{ok, _} ->
@@ -239,6 +241,7 @@ handle_info({'EXIT', Pid, spawn_error}, State) ->
{noreply, flush_waiters(NewState, Lang)};
handle_info({'EXIT', Pid, Reason}, State) ->
+ ?LOG_INFO(#{what => os_process_failure, pid => Pid, details => Reason}),
couch_log:info("~p ~p died ~p", [?MODULE, Pid, Reason]),
case ets:lookup(?PROCS, Pid) of
[#proc_int{} = Proc] ->
@@ -321,6 +324,11 @@ find_proc(#client{lang = Lang, ddoc = DDoc, ddoc_key = DDocKey} = Client) ->
find_proc(Lang, Fun) ->
try iter_procs(Lang, Fun)
catch error:Reason:StackTrace ->
+ ?LOG_ERROR(#{
+ what => os_process_not_available,
+ details => Reason,
+ stacktrace => StackTrace
+ }),
couch_log:error("~p ~p ~p", [?MODULE, Reason, StackTrace]),
{error, Reason}
end.
diff --git a/src/couch_js/src/couch_js_query_servers.erl b/src/couch_js/src/couch_js_query_servers.erl
index 80ceb3d..7dbacc6 100644
--- a/src/couch_js/src/couch_js_query_servers.erl
+++ b/src/couch_js/src/couch_js_query_servers.erl
@@ -25,6 +25,7 @@
-export([get_os_process/1, get_ddoc_process/2, ret_os_process/1]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(SUMERROR, <<"The _sum function requires that map values be numbers, "
"arrays of numbers, or objects. Objects cannot be mixed with other "
@@ -264,6 +265,12 @@ check_sum_overflow(InSize, OutSize, Sum) ->
end.
log_sum_overflow(InSize, OutSize) ->
+ ?LOG_ERROR(#{
+ what => reduce_function_overflow,
+ input_size => InSize,
+ output_size => OutSize,
+ details => "reduce output must shrink more rapidly"
+ }),
Fmt = "Reduce output must shrink more rapidly: "
"input size: ~b "
"output size: ~b",
diff --git a/src/couch_replicator/src/couch_replicator.erl b/src/couch_replicator/src/couch_replicator.erl
index a690d37..a0c6d2b 100644
--- a/src/couch_replicator/src/couch_replicator.erl
+++ b/src/couch_replicator/src/couch_replicator.erl
@@ -38,6 +38,7 @@
-include_lib("ibrowse/include/ibrowse.hrl").
-include_lib("couch/include/couch_db.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-spec replicate({[_]}, any()) ->
@@ -287,6 +288,7 @@ cancel_replication(JobId) when is_binary(JobId) ->
_ ->
JobId
end,
+ ?LOG_NOTICE(#{what => cancel_replication, in => replicator, id => Id}),
couch_log:notice("Canceling replication '~s'", [Id]),
case couch_replicator_jobs:remove_job(JTx, JobId) of
{error, not_found} ->
@@ -327,6 +329,13 @@ process_change(#{} = Db, #doc{deleted = false} = Doc) ->
?ST_PENDING, null, DocState)
end,
+ ?LOG_NOTICE(#{
+ what => replication_update,
+ db => DbName,
+ docid => DocId,
+ job_id => JobId,
+ job_state => DocState
+ }),
LogMsg = "~p : replication doc update db:~s doc:~s job_id:~s doc_state:~s",
couch_log:notice(LogMsg, [?MODULE, DbName, DocId, JobId, DocState]),
diff --git a/src/couch_replicator/src/couch_replicator_api_wrap.erl b/src/couch_replicator/src/couch_replicator_api_wrap.erl
index 17e5bf2..424c3ec 100644
--- a/src/couch_replicator/src/couch_replicator_api_wrap.erl
+++ b/src/couch_replicator/src/couch_replicator_api_wrap.erl
@@ -21,6 +21,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_views/include/couch_views.hrl").
-include("couch_replicator_api_wrap.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([
db_open/1,
@@ -178,6 +179,12 @@ open_doc_revs(#httpdb{retries = 0} = HttpDb, Id, Revs, Options, _Fun, _Acc) ->
Url = couch_util:url_strip_password(
couch_replicator_httpc:full_url(HttpDb, [{path,Path}, {qs,QS}])
),
+ ?LOG_ERROR(#{
+ what => permanent_request_failure,
+ in => replicator,
+ url => Url,
+ retries_remaining => 0
+ }),
couch_log:error("Replication crashing because GET ~s failed", [Url]),
exit(kaboom);
open_doc_revs(#httpdb{} = HttpDb, Id, Revs, Options, Fun, Acc) ->
@@ -244,6 +251,13 @@ open_doc_revs(#httpdb{} = HttpDb, Id, Revs, Options, Fun, Acc) ->
true ->
throw(request_uri_too_long);
false ->
+ ?LOG_INFO(#{
+ what => request_uri_too_long,
+ in => replicator,
+ docid => Id,
+ new_max_length => NewMaxLen,
+ details => "reducing url length because of 414 response"
+ }),
couch_log:info("Reducing url length to ~B because of"
" 414 response", [NewMaxLen]),
Options1 = lists:keystore(max_url_len, 1, Options,
@@ -256,6 +270,13 @@ open_doc_revs(#httpdb{} = HttpDb, Id, Revs, Options, Fun, Acc) ->
),
#httpdb{retries = Retries, wait = Wait0} = HttpDb,
Wait = 2 * erlang:min(Wait0 * 2, ?MAX_WAIT),
+ ?LOG_NOTICE(#{
+ what => retry_request,
+ in => replicator,
+ url => Url,
+ delay => Wait / 1000,
+ details => error_reason(Else)
+ }),
couch_log:notice("Retrying GET to ~s in ~p seconds due to error ~w",
[Url, Wait / 1000, error_reason(Else)]
),
diff --git a/src/couch_replicator/src/couch_replicator_auth_session.erl b/src/couch_replicator/src/couch_replicator_auth_session.erl
index a59c770..9526dc5 100644
--- a/src/couch_replicator/src/couch_replicator_auth_session.erl
+++ b/src/couch_replicator/src/couch_replicator_auth_session.erl
@@ -74,6 +74,7 @@
-include_lib("ibrowse/include/ibrowse.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
+-include_lib("kernel/include/logger.hrl").
-type headers() :: [{string(), string()}].
@@ -156,6 +157,11 @@ handle_call({update_headers, Headers, _Epoch}, _From, State) ->
Headers1 = [{"Cookie", Cookie} | Headers],
{reply, {Headers1, State1#state.epoch}, State1};
{error, Error} ->
+ ?LOG_ERROR(#{
+ what => terminate_session_auth_plugin,
+ in => replicator,
+ details => Error
+ }),
LogMsg = "~p: Stopping session auth plugin because of error ~p",
couch_log:error(LogMsg, [?MODULE, Error]),
{stop, Error, State}
@@ -170,11 +176,13 @@ handle_call(stop, _From, State) ->
handle_cast(Msg, State) ->
+ ?LOG_ERROR(#{what => unexpected_cast, in => replicator, msg => Msg}),
couch_log:error("~p: Received un-expected cast ~p", [?MODULE, Msg]),
{noreply, State}.
handle_info(Msg, State) ->
+ ?LOG_ERROR(#{what => unexpected_msg, in => replicator, msg => Msg}),
couch_log:error("~p : Received un-expected message ~p", [?MODULE, Msg]),
{noreply, State}.
@@ -307,6 +315,11 @@ process_response(Code, Headers, _Epoch, State) when Code >= 200, Code < 300 ->
{error, cookie_not_found} ->
State;
{error, Other} ->
+ ?LOG_ERROR(#{
+ what => cookie_parse_error,
+ in => replicator,
+ details => Other
+ }),
LogMsg = "~p : Could not parse cookie from response headers ~p",
couch_log:error(LogMsg, [?MODULE, Other]),
State
diff --git a/src/couch_replicator/src/couch_replicator_changes_reader.erl b/src/couch_replicator/src/couch_replicator_changes_reader.erl
index 6adf1af..b0bcb54 100644
--- a/src/couch_replicator/src/couch_replicator_changes_reader.erl
+++ b/src/couch_replicator/src/couch_replicator_changes_reader.erl
@@ -21,6 +21,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
start_link(StartSeq, #httpdb{} = Db, ChangesQueue, #{} = Options) ->
@@ -60,14 +61,23 @@ read_changes(Parent, StartSeq, Db, ChangesQueue, Options) ->
N when N > 0 ->
put(retries_left, N - 1),
LastSeq = get(last_seq),
+ LogMsg = #{
+ what => retry_changes_feed,
+ in => replicator,
+ source => couch_replicator_api_wrap:db_uri(Db),
+ sequence => LastSeq,
+ retries_remaining => N
+ },
Db2 = case LastSeq of
StartSeq ->
+ ?LOG_NOTICE(maps:merge(LogMsg, #{delay => Db#httpdb.wait / 1000})),
couch_log:notice("Retrying _changes request to source database ~s"
" with since=~p in ~p seconds",
[couch_replicator_api_wrap:db_uri(Db), LastSeq, Db#httpdb.wait / 1000]),
ok = timer:sleep(Db#httpdb.wait),
Db#httpdb{wait = 2 * Db#httpdb.wait};
_ ->
+ ?LOG_NOTICE(LogMsg),
couch_log:notice("Retrying _changes request to source database ~s"
" with since=~p", [couch_replicator_api_wrap:db_uri(Db), LastSeq]),
Db
@@ -82,6 +92,12 @@ read_changes(Parent, StartSeq, Db, ChangesQueue, Options) ->
process_change(#doc_info{id = <<>>} = DocInfo, {_, Db, _, _}) ->
% Previous CouchDB releases had a bug which allowed a doc with an empty ID
% to be inserted into databases. Such doc is impossible to GET.
+ ?LOG_ERROR(#{
+ what => ignore_empty_docid,
+ in => replicator,
+ source => couch_replicator_api_wrap:db_uri(Db),
+ sequence => DocInfo#doc_info.high_seq
+ }),
couch_log:error("Replicator: ignoring document with empty ID in "
"source database `~s` (_changes sequence ~p)",
[couch_replicator_api_wrap:db_uri(Db), DocInfo#doc_info.high_seq]);
@@ -90,6 +106,13 @@ process_change(#doc_info{id = Id} = DocInfo, {Parent, Db, ChangesQueue, _}) ->
case is_doc_id_too_long(byte_size(Id)) of
true ->
SourceDb = couch_replicator_api_wrap:db_uri(Db),
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ source => SourceDb,
+ docid => Id,
+ details => "document ID too long"
+ }),
couch_log:error("Replicator: document id `~s...` from source db "
" `~64s` is too long, ignoring.", [Id, SourceDb]),
Stats = couch_replicator_stats:new([{doc_write_failures, 1}]),
diff --git a/src/couch_replicator/src/couch_replicator_connection.erl b/src/couch_replicator/src/couch_replicator_connection.erl
index f31baf4..ace93d5 100644
--- a/src/couch_replicator/src/couch_replicator_connection.erl
+++ b/src/couch_replicator/src/couch_replicator_connection.erl
@@ -40,6 +40,7 @@
]).
-include_lib("ibrowse/include/ibrowse.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(DEFAULT_CLOSE_INTERVAL, 90000).
-define(RELISTEN_DELAY, 5000).
@@ -232,6 +233,13 @@ maybe_log_worker_death(_Host, _Port, normal) ->
ok;
maybe_log_worker_death(Host, Port, Reason) ->
+ ?LOG_INFO(#{
+ what => connection_failed,
+ in => replicator,
+ host => Host,
+ port => Port,
+ details => Reason
+ }),
ErrMsg = "Replication connection to: ~p:~p died with reason ~p",
couch_log:info(ErrMsg, [Host, Port, Reason]).
diff --git a/src/couch_replicator/src/couch_replicator_docs.erl b/src/couch_replicator/src/couch_replicator_docs.erl
index f84d129..b7fa937 100644
--- a/src/couch_replicator/src/couch_replicator_docs.erl
+++ b/src/couch_replicator/src/couch_replicator_docs.erl
@@ -24,6 +24,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(OWNER, <<"owner">>).
@@ -67,6 +68,13 @@ update_failed(null, null, null, _) ->
update_failed(DbName, DbUUID, DocId, Error) ->
Reason = error_reason(Error),
+ ?LOG_ERROR(#{
+ what => replication_failed,
+ in => replicator,
+ replicator_db => DbName,
+ replicator_doc => DocId,
+ details => Reason
+ }),
couch_log:error("Error processing replication doc `~s` from `~s`: ~s",
[DocId, DbName, Reason]),
update_rep_doc(DbName, DbUUID, DocId, [
@@ -154,9 +162,17 @@ update_rep_doc(RepDbName, RepDbUUID, RepDocId, KVs, Wait)
end
catch
throw:conflict ->
+ Delay = couch_rand:uniform(erlang:min(128, Wait)) * 100,
+ ?LOG_ERROR(#{
+ what => replication_doc_conflict,
+ in => replicator,
+ replication_db => RepDbName,
+ replication_doc => RepDocId,
+ retry_delay => Delay
+ }),
Msg = "Conflict when updating replication doc `~s`. Retrying.",
couch_log:error(Msg, [RepDocId]),
- ok = timer:sleep(couch_rand:uniform(erlang:min(128, Wait)) * 100),
+ ok = timer:sleep(Delay),
update_rep_doc(RepDbName, RepDbUUID, RepDocId, KVs, Wait * 2)
end;
@@ -213,6 +229,13 @@ save_rep_doc(DbName, DbUUID, Doc) when is_binary(DbName), is_binary(DbUUID) ->
% updating replication documents. Avoid crashing replicator and thus
% preventing all other replication jobs on the node from running.
throw:{forbidden, Reason} ->
+ ?LOG_ERROR(#{
+ what => replication_doc_update_forbidden,
+ in => replicator,
+ replication_db => DbName,
+ replication_doc => Doc#doc.id,
+ details => Reason
+ }),
Msg = "~p VDU or BDU function preventing doc update to ~s ~s ~p",
couch_log:error(Msg, [?MODULE, DbName, Doc#doc.id, Reason]),
{ok, forbidden}
diff --git a/src/couch_replicator/src/couch_replicator_httpc.erl b/src/couch_replicator/src/couch_replicator_httpc.erl
index 52baa39..d45a019 100644
--- a/src/couch_replicator/src/couch_replicator_httpc.erl
+++ b/src/couch_replicator/src/couch_replicator_httpc.erl
@@ -15,6 +15,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("ibrowse/include/ibrowse.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([setup/1]).
-export([send_req/3]).
@@ -55,6 +56,12 @@ setup(Db) ->
{error, Error} ->
LogMsg = "~p: auth plugin initialization failed ~p ~p",
LogUrl = couch_util:url_strip_password(Url),
+ ?LOG_ERROR(#{
+ what => auth_plugin_initialization_failure,
+ in => replicator,
+ db => LogUrl,
+ details => Error
+ }),
couch_log:error(LogMsg, [?MODULE, LogUrl, Error]),
throw({replication_auth_error, Error})
end.
@@ -348,6 +355,14 @@ update_first_error_timestamp(HttpDb) ->
log_retry_error(Params, HttpDb, Wait, Error) ->
Method = string:to_upper(atom_to_list(get_value(method, Params, get))),
Url = couch_util:url_strip_password(full_url(HttpDb, Params)),
+ ?LOG_NOTICE(#{
+ what => retry_request,
+ in => replicator,
+ method => Method,
+ url => Url,
+ retry_delay => Wait / 1000,
+ details => error_cause(Error)
+ }),
couch_log:notice("Retrying ~s request to ~s in ~p seconds due to error ~s",
[Method, Url, Wait / 1000, error_cause(Error)]).
@@ -360,10 +375,24 @@ report_error(_Worker, HttpDb, Params, Error) ->
do_report_error(Url, Method, {code, Code}) ->
+ ?LOG_ERROR(#{
+ what => failed_request,
+ in => replicator,
+ method => Method,
+ url => Url,
+ status_code => Code
+ }),
couch_log:error("Replicator, request ~s to ~p failed. The received "
"HTTP error code is ~p", [Method, Url, Code]);
do_report_error(FullUrl, Method, Error) ->
+ ?LOG_ERROR(#{
+ what => failed_request,
+ in => replicator,
+ method => Method,
+ url => FullUrl,
+ details => error_cause(Error)
+ }),
couch_log:error("Replicator, request ~s to ~p failed due to error ~s",
[Method, FullUrl, error_cause(Error)]).
diff --git a/src/couch_replicator/src/couch_replicator_job.erl b/src/couch_replicator/src/couch_replicator_job.erl
index 8cfb426..3c07fdd 100644
--- a/src/couch_replicator/src/couch_replicator_job.erl
+++ b/src/couch_replicator/src/couch_replicator_job.erl
@@ -39,6 +39,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(LOWEST_SEQ, 0).
@@ -116,6 +117,12 @@ terminate(shutdown, #rep_state{} = State0) ->
{ok, State2} ->
State2;
Error ->
+ ?LOG_ERROR(#{
+ what => checkpoint_failure,
+ in => replicator,
+ jobid => State1#rep_state.id,
+ details => Error
+ }),
Msg = "~p : Failed last checkpoint. Job: ~p Error: ~p",
couch_log:error(Msg, [?MODULE, State1#rep_state.id, Error]),
State1
@@ -127,9 +134,20 @@ terminate(shutdown, #rep_state{} = State0) ->
terminate({shutdown, Error}, {init_error, Stack}) ->
% Termination in init, before the job had initialized
case Error of
- max_backoff -> couch_log:warning("~p job backed off", [?MODULE]);
- finished -> couch_log:notice("~p job finished in init", [?MODULE]);
- _ -> couch_log:error("~p job failed ~p ~p", [?MODULE, Error, Stack])
+ max_backoff ->
+ ?LOG_WARNING(#{what => job_backoff, in => replicator}),
+ couch_log:warning("~p job backed off", [?MODULE]);
+ finished ->
+ ?LOG_NOTICE(#{what => job_finished_during_init, in => replicator}),
+ couch_log:notice("~p job finished in init", [?MODULE]);
+ _ ->
+ ?LOG_ERROR(#{
+ what => job_failure,
+ in => replicator,
+ details => Error,
+ stacktrace => Stack
+ }),
+ couch_log:error("~p job failed ~p ~p", [?MODULE, Error, Stack])
end,
ok;
@@ -139,6 +157,11 @@ terminate({shutdown, finished}, #rep_state{} = State) ->
terminate({shutdown, halt}, #rep_state{} = State) ->
% Job is re-enqueued and possibly already running somewhere else
+ ?LOG_ERROR(#{
+ what => job_halted,
+ in => replicator,
+ jobid => State#rep_state.id
+ }),
couch_log:error("~p job ~p halted", [?MODULE, State#rep_state.id]),
ok = close_endpoints(State);
@@ -155,6 +178,14 @@ terminate(Reason0, #rep_state{} = State0) ->
source_name = Source,
target_name = Target
} = State,
+ ?LOG_ERROR(#{
+ what => job_failure,
+ in => replicator,
+ replication_id => RepId,
+ source => Source,
+ target => Target,
+ details => Reason
+ }),
couch_log:error("Replication `~s` (`~s` -> `~s`) failed: ~p",
[RepId, Source, Target, Reason]),
ok = reschedule_on_error(undefined, Job, JobData, Reason),
@@ -189,6 +220,21 @@ handle_call({report_seq_done, Seq, StatsInc}, From, #rep_state{} = State) ->
_ ->
NewThroughSeq0
end,
+ ?LOG_DEBUG(#{
+ what => progress_report,
+ in => replicator,
+ old => #{
+ highest_seq_done => HighestDone,
+ current_through_seq => ThroughSeq,
+ seqs_in_progress => SeqsInProgress
+ },
+ new => #{
+ highest_seq_done => NewHighestDone,
+ current_through_seq => NewThroughSeq,
+ seqs_in_progress => NewSeqsInProgress
+ },
+ worker_reported_seq => Seq
+ }),
couch_log:debug("Worker reported seq ~p, through seq was ~p, "
"new through seq is ~p, highest seq done was ~p, "
"new highest seq done is ~p~n"
@@ -251,10 +297,12 @@ handle_info(shutdown, St) ->
{stop, shutdown, St};
handle_info({'EXIT', Pid, max_backoff}, State) ->
+ ?LOG_ERROR(#{what => max_backoff, in => replicator, pid => Pid}),
couch_log:error("Max backoff reached child process ~p", [Pid]),
{stop, {shutdown, max_backoff}, State};
handle_info({'EXIT', Pid, {shutdown, max_backoff}}, State) ->
+ ?LOG_ERROR(#{what => max_backoff, in => replicator, pid => Pid}),
couch_log:error("Max backoff reached child process ~p", [Pid]),
{stop, {shutdown, max_backoff}, State};
@@ -273,6 +321,7 @@ handle_info({'EXIT', Pid, Reason0}, #rep_state{changes_reader=Pid} = State) ->
Other ->
{changes_reader_died, Other}
end,
+ ?LOG_ERROR(#{what => changes_reader_crash, in => replicator, details => Reason}),
couch_log:error("ChangesReader process died with reason: ~p", [Reason]),
{stop, {shutdown, Reason}, cancel_timers(State)};
@@ -281,6 +330,7 @@ handle_info({'EXIT', Pid, normal}, #rep_state{changes_manager=Pid} = State) ->
handle_info({'EXIT', Pid, Reason}, #rep_state{changes_manager=Pid} = State) ->
couch_stats:increment_counter([couch_replicator, changes_manager_deaths]),
+ ?LOG_ERROR(#{what => changes_manager_crash, in => replicator, details => Reason}),
couch_log:error("ChangesManager process died with reason: ~p", [Reason]),
{stop, {shutdown, {changes_manager_died, Reason}}, cancel_timers(State)};
@@ -289,6 +339,7 @@ handle_info({'EXIT', Pid, normal}, #rep_state{changes_queue=Pid} = State) ->
handle_info({'EXIT', Pid, Reason}, #rep_state{changes_queue=Pid} = State) ->
couch_stats:increment_counter([couch_replicator, changes_queue_deaths]),
+ ?LOG_ERROR(#{what => changes_queue_crash, in => replicator, details => Reason}),
couch_log:error("ChangesQueue process died with reason: ~p", [Reason]),
{stop, {shutdown, {changes_queue_died, Reason}}, cancel_timers(State)};
@@ -297,6 +348,12 @@ handle_info({'EXIT', Pid, normal}, #rep_state{workers = Workers} = State) ->
Workers ->
%% Processes might be linked by replicator's auth plugins so
%% we tolerate them exiting `normal` here and don't crash
+ ?LOG_WARNING(#{
+ what => unknown_process_exit,
+ in => replicator,
+ pid => Pid,
+ reason => normal
+ }),
LogMsg = "~p: unknown pid exited `normal` ~p",
couch_log:error(LogMsg, [?MODULE, Pid]),
{noreply, State#rep_state{workers = Workers}};
@@ -319,6 +376,12 @@ handle_info({'EXIT', Pid, Reason}, #rep_state{workers = Workers} = State) ->
{shutdown, _} = Err ->
Err;
Other ->
+ ?LOG_ERROR(#{
+ what => worker_crash,
+ in => replicator,
+ pid => Pid,
+ details => Reason
+ }),
ErrLog = "Worker ~p died with reason: ~p",
couch_log:error(ErrLog, [Pid, Reason]),
{worker_died, Pid, Other}
@@ -327,6 +390,11 @@ handle_info({'EXIT', Pid, Reason}, #rep_state{workers = Workers} = State) ->
end;
handle_info({Ref, ready}, St) when is_reference(Ref) ->
+ ?LOG_NOTICE(#{
+ what => spurious_future_ready_message,
+ in => replicator,
+ ref => Ref
+ }),
LogMsg = "~p : spurious erlfdb future ready message ~p",
couch_log:notice(LogMsg, [?MODULE, Ref]),
{noreply, St};
@@ -411,6 +479,12 @@ delayed_init() ->
{stop, {shutdown, Exit}, {init_error, Stack}};
_Tag:Error:Stack ->
Reason = {error, replication_start_error(Error)},
+ ?LOG_ERROR(#{
+ what => job_failure_during_init,
+ job => Job,
+ details => Reason,
+ stacktrace => Stack
+ }),
ErrMsg = "~p : job ~p failed during startup ~p stack:~p",
couch_log:error(ErrMsg, [?MODULE, Job, Reason, Stack]),
reschedule_on_error(undefined, Job, JobData, Reason),
@@ -571,12 +645,25 @@ check_ownership(#{jtx := true} = JTx, Job, JobData) ->
fail_job(JTx, Job, JobData, Error),
not_owner;
{ok, #{}} ->
+ ?LOG_WARNING(#{
+ what => duplicate_job_detected,
+ in => replicator,
+ jobid => JobId,
+ other_jobid => OtherJobId,
+ replication_id => RepId
+ }),
LogMsg = "~p : Job ~p usurping job ~p for replication ~p",
couch_log:warning(LogMsg, [?MODULE, JobId, OtherJobId,
RepId]),
couch_replicator_jobs:update_rep_id(JTx, JobId, RepId),
owner;
{error, not_found} ->
+ ?LOG_ERROR(#{
+ what => orphaned_job_mapping,
+ in => replicator,
+ replication_id => RepId,
+ jobid => OtherJobId
+ }),
LogMsg = "~p : Orphan replication job reference ~p -> ~p",
couch_log:error(LogMsg, [?MODULE, RepId, OtherJobId]),
couch_replicator_jobs:update_rep_id(JTx, JobId, RepId),
@@ -861,6 +948,11 @@ state_strip_creds(#rep_state{source = Source, target = Target} = State) ->
adjust_maxconn(Src = #{<<"http_connections">> := 1}, RepId) ->
+ ?LOG_NOTICE(#{
+ what => minimum_source_connections_override,
+ in => replicator,
+ details => "adjusting minimum source connections to 2"
+ }),
Msg = "Adjusting minimum number of HTTP source connections to 2 for ~p",
couch_log:notice(Msg, [RepId]),
Src#{<<"http_connections">> := 2};
@@ -960,7 +1052,21 @@ init_state(#{} = Job, #{} = JobData) ->
[SourceLog, TargetLog] = find_and_migrate_logs([Source, Target], Rep,
BaseId),
- {StartSeq0, History} = compare_replication_logs(SourceLog, TargetLog),
+ {StartSeq0, History, MatchedSessionIds} = compare_replication_logs(SourceLog, TargetLog),
+
+ if not MatchedSessionIds ->
+ ?LOG_NOTICE(#{
+ what => session_history_mismatch,
+ in => replicator,
+ calculated_start_seq => StartSeq0,
+ source => couch_replicator_api_wrap:db_uri(Source),
+ target => couch_replicator_api_wrap:db_uri(Target),
+ replication_id => Id,
+ details => "scanned histories to find common ancestor"
+ });
+ true ->
+ ok
+ end,
#{?REP_STATS := Stats0} = JobData,
Stats1 = couch_replicator_stats:new(Stats0),
@@ -1043,6 +1149,13 @@ maybe_save_migrated_log(#{?OPTIONS := Options}, Db, #doc{} = Doc, OldId) ->
case maps:get(<<"use_checkpoints">>, Options) of
true ->
update_checkpoint(Db, Doc),
+ ?LOG_NOTICE(#{
+ what => migrated_checkpoint,
+ in => replicator,
+ db => httpdb_strip_creds(Db),
+ old_id => OldId,
+ new_id => Doc#doc.id
+ }),
Msg = "Migrated replication checkpoint. Db:~p ~p -> ~p",
couch_log:notice(Msg, [httpdb_strip_creds(Db), OldId, Doc#doc.id]);
false ->
@@ -1111,6 +1224,13 @@ do_checkpoint(State) ->
{checkpoint_commit_failure, <<"Failure on target commit: ",
(couch_util:to_binary(Reason))/binary>>};
{SrcInstanceStartTime, TgtInstanceStartTime} ->
+ ?LOG_NOTICE(#{
+ what => checkpoint,
+ in => replicator,
+ source => SourceName,
+ target => TargetName,
+ sequence => NewSeq
+ }),
couch_log:notice("recording a checkpoint for `~s` -> `~s` at "
"source update_seq ~p", [SourceName, TargetName, NewSeq]),
StartTime = couch_replicator_utils:rfc1123_local(RepStartTime),
@@ -1271,7 +1391,7 @@ compare_replication_logs(SrcDoc, TgtDoc) ->
OldSeqNum = get_value(<<"source_last_seq">>, RepRecProps,
?LOWEST_SEQ),
OldHistory = get_value(<<"history">>, RepRecProps, []),
- {OldSeqNum, OldHistory};
+ {OldSeqNum, OldHistory, true};
false ->
SourceHistory = get_value(<<"history">>, RepRecProps, []),
TargetHistory = get_value(<<"history">>, RepRecPropsTgt, []),
@@ -1279,7 +1399,8 @@ compare_replication_logs(SrcDoc, TgtDoc) ->
"Scanning histories to find a common ancestor.", []),
couch_log:debug("Record on source:~p~nRecord on target:~p~n",
[RepRecProps, RepRecPropsTgt]),
- compare_rep_history(SourceHistory, TargetHistory)
+ {StartSeq, History} = compare_rep_history(SourceHistory, TargetHistory),
+ {StartSeq, History, false}
end.
@@ -1426,6 +1547,17 @@ log_replication_start(#rep_state{} = RepState) ->
_ ->
"from _replicate endpoint"
end,
+ ?LOG_NOTICE(#{
+ what => starting_replication,
+ in => replicator,
+ source => Source,
+ target => Target,
+ replication_db => DbName,
+ replication_doc => DocId,
+ session_id => Sid,
+ worker_processes => Workers,
+ worker_batch_size => BatchSize
+ }),
Msg = "Starting replication ~s (~s -> ~s) ~s worker_procesess:~p"
" worker_batch_size:~p session_id:~s",
couch_log:notice(Msg, [Id, Source, Target, From, Workers, BatchSize, Sid]).
@@ -1442,6 +1574,13 @@ check_user_filter(#rep_state{} = State) ->
{RepId, BaseId} ->
ok;
{NewId, NewBaseId} when is_binary(NewId), is_binary(NewBaseId) ->
+ ?LOG_ERROR(#{
+ what => replication_id_updated,
+ in => replicator,
+ old_id => RepId,
+ new_id => NewId,
+ details => "replication job shutting down"
+ }),
LogMsg = "~p : Replication id was updated ~p -> ~p",
couch_log:error(LogMsg, [?MODULE, RepId, NewId]),
reschedule(undefined, Job, JobData),
diff --git a/src/couch_replicator/src/couch_replicator_job_server.erl b/src/couch_replicator/src/couch_replicator_job_server.erl
index a2e90b0..2452a22 100644
--- a/src/couch_replicator/src/couch_replicator_job_server.erl
+++ b/src/couch_replicator/src/couch_replicator_job_server.erl
@@ -38,6 +38,7 @@
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(MAX_ACCEPTORS, 2).
@@ -95,6 +96,11 @@ handle_call({accepted, Pid, Normal}, _From, #{} = St) ->
},
{reply, ok, spawn_acceptors(St1)};
false ->
+ ?LOG_ERROR(#{
+ what => unknown_acceptor,
+ in => replicator,
+ pid => Pid
+ }),
LogMsg = "~p : unknown acceptor processs ~p",
couch_log:error(LogMsg, [?MODULE, Pid]),
{stop, {unknown_acceptor_pid, Pid}, St}
@@ -234,6 +240,11 @@ transient_job_cleanup(#{} = St) ->
case State =:= finished andalso IsTransient andalso IsOld of
true ->
ok = couch_replicator_jobs:remove_job(undefined, JobId),
+ ?LOG_INFO(#{
+ what => removing_old_job,
+ in => replicator,
+ jobid => JobId
+ }),
couch_log:info("~p : Removed old job ~p", [?MODULE, JobId]),
ok;
false ->
@@ -301,6 +312,11 @@ wait_jobs_exit(#{} = Jobs, Timeout) ->
wait_jobs_exit(maps:remove(Pid, Jobs), Timeout)
after
Timeout ->
+ ?LOG_ERROR(#{
+ what => unclean_job_termination,
+ in => replicator,
+ job_count => map_size(Jobs)
+ }),
LogMsg = "~p : ~p jobs didn't terminate cleanly",
couch_log:error(LogMsg, [?MODULE, map_size(Jobs)]),
ok
@@ -329,6 +345,12 @@ spawn_acceptors(St) ->
handle_acceptor_exit(#{acceptors := Acceptors} = St, Pid, Reason) ->
St1 = St#{acceptors := maps:remove(Pid, Acceptors)},
+ ?LOG_ERROR(#{
+ what => acceptor_crash,
+ in => replicator,
+ pid => Pid,
+ details => Reason
+ }),
LogMsg = "~p : acceptor process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{noreply, spawn_acceptors(St1)}.
@@ -344,6 +366,12 @@ handle_worker_exit(#{workers := Workers} = St, Pid, Reason) ->
{shutdown, _} ->
ok;
_ ->
+ ?LOG_ERROR(#{
+ what => worker_crash,
+ in => replicator,
+ pid => Pid,
+ details => Reason
+ }),
LogMsg = "~p : replicator job process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason])
end,
@@ -351,6 +379,11 @@ handle_worker_exit(#{workers := Workers} = St, Pid, Reason) ->
handle_unknown_exit(St, Pid, Reason) ->
+ ?LOG_ERROR(#{
+ what => unknown_process_crash,
+ in => replicator,
+ pid => Pid
+ }),
LogMsg = "~p : unknown process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{stop, {unknown_pid_exit, Pid}, St}.
diff --git a/src/couch_replicator/src/couch_replicator_parse.erl b/src/couch_replicator/src/couch_replicator_parse.erl
index 5b3f3f3..ac25bee 100644
--- a/src/couch_replicator/src/couch_replicator_parse.erl
+++ b/src/couch_replicator/src/couch_replicator_parse.erl
@@ -23,6 +23,7 @@
-include_lib("ibrowse/include/ibrowse.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(DEFAULT_SOCK_OPTS, "[{keepalive, true}, {nodelay, false}]").
@@ -60,10 +61,23 @@ parse_rep_doc(RepDoc) ->
parse_rep(RepDoc, null)
catch
throw:{error, Reason}:Stack ->
+ ?LOG_ERROR(#{
+ what => replication_doc_parse_error,
+ in => replicator,
+ details => Reason,
+ stacktrace => Stack
+ }),
LogErr1 = "~p parse_rep_doc fail ~p ~p",
couch_log:error(LogErr1, [?MODULE, Reason, Stack]),
throw({bad_rep_doc, Reason});
Tag:Err:Stack ->
+ ?LOG_ERROR(#{
+ what => replication_doc_parse_error,
+ in => replicator,
+ tag => Tag,
+ details => Err,
+ stacktrace => Stack
+ }),
LogErr2 = "~p parse_rep_doc fail ~p:~p ~p",
couch_log:error(LogErr2, [?MODULE, Tag, Err, Stack]),
throw({bad_rep_doc, couch_util:to_binary({Tag, Err})})
@@ -82,10 +96,23 @@ parse_transient_rep(#{} = Body, UserName) ->
parse_rep(Body, UserName)
catch
throw:{error, Reason}:Stack ->
+ ?LOG_ERROR(#{
+ what => transient_replication_parse_error,
+ in => replicator,
+ details => Reason,
+ stacktrace => Stack
+ }),
LogErr1 = "~p parse_transient_rep fail ~p ~p",
couch_log:error(LogErr1, [?MODULE, Reason, Stack]),
throw({bad_request, Reason});
Tag:Err:Stack ->
+ ?LOG_ERROR(#{
+ what => transient_replication_parse_error,
+ in => replicator,
+ tag => Tag,
+ details => Err,
+ stacktrace => Stack
+ }),
LogErr2 = "~p parse_transient_rep fail ~p ~p",
couch_log:error(LogErr2, [?MODULE, Tag, Err, Stack]),
throw({bad_request, couch_util:to_binary({Tag, Err})})
diff --git a/src/couch_replicator/src/couch_replicator_worker.erl b/src/couch_replicator/src/couch_replicator_worker.erl
index 4cd984c..d236b6b 100644
--- a/src/couch_replicator/src/couch_replicator_worker.erl
+++ b/src/couch_replicator/src/couch_replicator_worker.erl
@@ -25,6 +25,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_replicator/include/couch_replicator_api_wrap.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
% TODO: maybe make both buffer max sizes configurable
-define(DOC_BUFFER_BYTE_SIZE, 512 * 1024). % for remote targets
@@ -225,6 +226,11 @@ queue_fetch_loop(Source, Target, Parent, Cp, ChangesManager) ->
{ok, Stats} = gen_server:call(Parent, flush, infinity),
ok = gen_server:call(Cp, {report_seq_done, ReportSeq, Stats}, infinity),
erlang:put(last_stats_report, os:timestamp()),
+ ?LOG_DEBUG(#{
+ what => worker_progress_report,
+ in => replicator,
+ seq => ReportSeq
+ }),
couch_log:debug("Worker reported completion of seq ~p", [ReportSeq]),
queue_fetch_loop(Source, Target, Parent, Cp, ChangesManager)
end.
@@ -265,6 +271,14 @@ fetch_doc(Source, {Id, Revs, PAs}, DocHandler, Acc) ->
[Id, couch_doc:revs_to_strs(Revs)]),
WaitMSec = config:get_integer("replicator", "missing_doc_retry_msec",
?MISSING_DOC_RETRY_MSEC),
+ ?LOG_ERROR(#{
+ what => missing_document,
+ in => replicator,
+ source => couch_replicator_api_wrap:db_uri(Source),
+ docid => Id,
+ revisions => couch_doc:revs_to_strs(Revs),
+ retry_delay => WaitMSec / 1000
+ }),
timer:sleep(WaitMSec),
couch_replicator_api_wrap:open_doc_revs(Source, Id, Revs, [latest], DocHandler, Acc);
throw:{missing_stub, _} ->
@@ -273,6 +287,14 @@ fetch_doc(Source, {Id, Revs, PAs}, DocHandler, Acc) ->
[Id, couch_doc:revs_to_strs(Revs)]),
WaitMSec = config:get_integer("replicator", "missing_doc_retry_msec",
?MISSING_DOC_RETRY_MSEC),
+ ?LOG_ERROR(#{
+ what => missing_attachment_stub,
+ in => replicator,
+ source => couch_replicator_api_wrap:db_uri(Source),
+ docid => Id,
+ revisions => couch_doc:revs_to_strs(Revs),
+ retry_delay => WaitMSec / 1000
+ }),
timer:sleep(WaitMSec),
couch_replicator_api_wrap:open_doc_revs(Source, Id, Revs, [latest], DocHandler, Acc)
end.
@@ -282,6 +304,7 @@ remote_doc_handler({ok, #doc{id = <<?DESIGN_DOC_PREFIX, _/binary>>} = Doc},
Acc) ->
% Flush design docs in their own PUT requests to correctly process
% authorization failures for design doc updates.
+ ?LOG_DEBUG(#{what => flush_ddoc, in => replicator}),
couch_log:debug("Worker flushing design doc", []),
doc_handler_flush_doc(Doc, Acc);
remote_doc_handler({ok, #doc{atts = [_ | _]} = Doc}, Acc) ->
@@ -289,6 +312,7 @@ remote_doc_handler({ok, #doc{atts = [_ | _]} = Doc}, Acc) ->
% source. The data property of each attachment is a function that starts
% streaming the attachment data from the remote source, therefore it's
% convenient to call it ASAP to avoid ibrowse inactivity timeouts.
+ ?LOG_DEBUG(#{what => flush_doc_with_attachments, in => replicator}),
couch_log:debug("Worker flushing doc with attachments", []),
doc_handler_flush_doc(Doc, Acc);
remote_doc_handler({ok, #doc{atts = []} = Doc}, {Parent, _} = Acc) ->
@@ -314,6 +338,11 @@ doc_handler_flush_doc(#doc{} = Doc, {Parent, Target} = Acc) ->
spawn_writer(Target, #batch{docs = DocList, size = Size}) ->
case {Target, Size > 0} of
{#httpdb{}, true} ->
+ ?LOG_DEBUG(#{
+ what => flush_doc_batch,
+ in => replicator,
+ batch_size => Size
+ }),
couch_log:debug("Worker flushing doc batch of size ~p bytes", [Size]);
_ ->
ok
@@ -354,6 +383,11 @@ maybe_flush_docs(#httpdb{} = Target, Batch, Doc) ->
JsonDoc = ?JSON_ENCODE(couch_doc:to_json_obj(Doc, [revs, attachments])),
case SizeAcc + iolist_size(JsonDoc) of
SizeAcc2 when SizeAcc2 > ?DOC_BUFFER_BYTE_SIZE ->
+ ?LOG_DEBUG(#{
+ what => flush_doc_batch,
+ in => replicator,
+ batch_size => SizeAcc2
+ }),
couch_log:debug("Worker flushing doc batch of size ~p bytes", [SizeAcc2]),
Stats = flush_docs(Target, [JsonDoc | DocAcc]),
{#batch{}, Stats};
@@ -371,12 +405,27 @@ flush_docs(Target, DocList) ->
handle_flush_docs_result(FlushResult, Target, DocList).
-handle_flush_docs_result({error, request_body_too_large}, _Target, [Doc]) ->
+handle_flush_docs_result({error, request_body_too_large}, Target, [Doc]) ->
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ reason => request_body_too_large,
+ docid => extract_value(<<"_id">>, Doc)
+ }),
couch_log:error("Replicator: failed to write doc ~p. Too large", [Doc]),
couch_replicator_stats:new([{doc_write_failures, 1}]);
handle_flush_docs_result({error, request_body_too_large}, Target, DocList) ->
Len = length(DocList),
{DocList1, DocList2} = lists:split(Len div 2, DocList),
+ ?LOG_NOTICE(#{
+ what => split_large_batch,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ reason => request_body_too_large,
+ original_batch_size => Len,
+ details => "splitting into two smaller batches and retrying"
+ }),
couch_log:notice("Replicator: couldn't write batch of size ~p to ~p because"
" request body is too large. Splitting batch into 2 separate batches of"
" sizes ~p and ~p", [Len, couch_replicator_api_wrap:db_uri(Target),
@@ -388,6 +437,15 @@ handle_flush_docs_result({ok, Errors}, Target, DocList) ->
DbUri = couch_replicator_api_wrap:db_uri(Target),
lists:foreach(
fun({Props}) ->
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ docid => get_value(id, Props, undefined),
+ revision => get_value(rev, Props, undefined),
+ error => get_value(error, Props, undefined),
+ details => get_value(reason, Props, undefined)
+ }),
couch_log:error("Replicator: couldn't write document `~s`, revision"
" `~s`, to target database `~s`. Error: `~s`, reason: `~s`.", [
get_value(id, Props, ""), get_value(rev, Props, ""), DbUri,
@@ -400,12 +458,29 @@ handle_flush_docs_result({ok, Errors}, Target, DocList) ->
handle_flush_docs_result({error, {bulk_docs_failed, _, _} = Err}, _, _) ->
exit(Err).
+extract_value(Prop, Json) when is_binary(Json) ->
+ try
+ {Props} = ?JSON_DECODE(Json),
+ get_value(Prop, Props, undefined)
+ catch _:_ ->
+ undefined
+ end;
+extract_value(_, _) ->
+ undefined.
flush_doc(Target, #doc{id = Id, revs = {Pos, [RevId | _]}} = Doc) ->
try couch_replicator_api_wrap:update_doc(Target, Doc, [], replicated_changes) of
{ok, _} ->
ok;
Error ->
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ docid => Id,
+ revision => couch_doc:rev_to_str({Pos, RevId}),
+ details => Error
+ }),
couch_log:error("Replicator: error writing document `~s` to `~s`: ~s",
[Id, couch_replicator_api_wrap:db_uri(Target), couch_util:to_binary(Error)]),
Error
@@ -413,12 +488,29 @@ flush_doc(Target, #doc{id = Id, revs = {Pos, [RevId | _]}} = Doc) ->
throw:{missing_stub, _} = MissingStub ->
throw(MissingStub);
throw:{Error, Reason} ->
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ docid => Id,
+ revision => couch_doc:rev_to_str({Pos, RevId}),
+ error => Error,
+ details => Reason
+ }),
couch_log:error("Replicator: couldn't write document `~s`, revision `~s`,"
" to target database `~s`. Error: `~s`, reason: `~s`.",
[Id, couch_doc:rev_to_str({Pos, RevId}),
couch_replicator_api_wrap:db_uri(Target), to_binary(Error), to_binary(Reason)]),
{error, Error};
throw:Err ->
+ ?LOG_ERROR(#{
+ what => doc_write_failure,
+ in => replicator,
+ target => couch_replicator_api_wrap:db_uri(Target),
+ docid => Id,
+ revision => couch_doc:rev_to_str({Pos, RevId}),
+ details => Err
+ }),
couch_log:error("Replicator: couldn't write document `~s`, revision `~s`,"
" to target database `~s`. Error: `~s`.",
[Id, couch_doc:rev_to_str({Pos, RevId}),
diff --git a/src/couch_views/src/couch_views_indexer.erl b/src/couch_views/src/couch_views_indexer.erl
index eed3f54..7f0e2d5 100644
--- a/src/couch_views/src/couch_views_indexer.erl
+++ b/src/couch_views/src/couch_views_indexer.erl
@@ -31,6 +31,7 @@
-include("couch_views.hrl").
-include_lib("couch/include/couch_db.hrl").
-include_lib("fabric/include/fabric2.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(KEY_SIZE_LIMIT, 8000).
@@ -122,6 +123,14 @@ init() ->
error:database_does_not_exist ->
fail_job(Job, Data, db_deleted, "Database was deleted");
Error:Reason:Stack ->
+ ?LOG_ERROR(#{
+ what => view_update_failure,
+ db => DbName,
+ ddoc => DDocId,
+ tag => Error,
+ details => Reason,
+ stacktrace => Stack
+ }),
Fmt = "Error building view for ddoc ~s in ~s: ~p:~p ~p",
couch_log:error(Fmt, [DbName, DDocId, Error, Reason, Stack]),
@@ -592,6 +601,12 @@ check_kv_size_limit(Mrst, Doc, KeyLimit, ValLimit) ->
Doc
catch throw:{size_error, Type} ->
#{id := DocId} = Doc,
+ ?LOG_ERROR(#{
+ what => lists:concat(["oversized_", Type]),
+ db => DbName,
+ docid => DocId,
+ index => IdxName
+ }),
Fmt = "View ~s size error for docid `~s`, excluded from indexing "
"in db `~s` for design doc `~s`",
couch_log:error(Fmt, [Type, DocId, DbName, IdxName]),
@@ -662,6 +677,7 @@ report_progress(State, UpdateType) ->
{ok, Job2} ->
State#{job := Job2};
{error, halt} ->
+ ?LOG_ERROR(#{what => job_halted, job => Job1}),
couch_log:error("~s job halted :: ~w", [?MODULE, Job1]),
exit(normal)
end;
@@ -670,6 +686,7 @@ report_progress(State, UpdateType) ->
ok ->
State;
{error, halt} ->
+ ?LOG_ERROR(#{what => job_halted, job => Job1}),
couch_log:error("~s job halted :: ~w", [?MODULE, Job1]),
exit(normal)
end
diff --git a/src/couch_views/src/couch_views_server.erl b/src/couch_views/src/couch_views_server.erl
index 71a4abb..e94eaf1 100644
--- a/src/couch_views/src/couch_views_server.erl
+++ b/src/couch_views/src/couch_views_server.erl
@@ -15,6 +15,7 @@
-behaviour(gen_server).
+-include_lib("kernel/include/logger.hrl").
-export([
start_link/0
@@ -75,6 +76,7 @@ handle_call({accepted, Pid}, _From, St) ->
},
{reply, ok, spawn_acceptors(St1)};
false ->
+ ?LOG_ERROR(#{what => unknown_acceptor, pid => Pid}),
LogMsg = "~p : unknown acceptor processs ~p",
couch_log:error(LogMsg, [?MODULE, Pid]),
{stop, {unknown_acceptor_pid, Pid}, St}
@@ -127,6 +129,7 @@ format_status(_Opt, [_PDict, State]) ->
handle_acceptor_exit(#{acceptors := Acceptors} = St, Pid, Reason) ->
St1 = St#{acceptors := maps:remove(Pid, Acceptors)},
+ ?LOG_ERROR(#{what => acceptor_crash, pid => Pid, reason => Reason}),
LogMsg = "~p : acceptor process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{noreply, spawn_acceptors(St1)}.
@@ -138,12 +141,14 @@ handle_worker_exit(#{workers := Workers} = St, Pid, normal) ->
handle_worker_exit(#{workers := Workers} = St, Pid, Reason) ->
St1 = St#{workers := maps:remove(Pid, Workers)},
+ ?LOG_ERROR(#{what => indexer_crash, pid => Pid, reason => Reason}),
LogMsg = "~p : indexer process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{noreply, spawn_acceptors(St1)}.
handle_unknown_exit(St, Pid, Reason) ->
+ ?LOG_ERROR(#{what => unknown_process_crash, pid => Pid, reason => Reason}),
LogMsg = "~p : unknown process ~p exited with ~p",
couch_log:error(LogMsg, [?MODULE, Pid, Reason]),
{stop, {unknown_pid_exit, Pid}, St}.
diff --git a/src/couch_views/src/couch_views_sup.erl b/src/couch_views/src/couch_views_sup.erl
index 9453189..ee32d4e 100644
--- a/src/couch_views/src/couch_views_sup.erl
+++ b/src/couch_views/src/couch_views_sup.erl
@@ -16,6 +16,7 @@
-behaviour(supervisor).
+-include_lib("kernel/include/logger.hrl").
-export([
start_link/0
@@ -46,6 +47,7 @@ init(normal) ->
{ok, {flags(), Children}};
init(builds_disabled) ->
+ ?LOG_NOTICE(#{what => view_indexing_disabled}),
couch_log:notice("~p : view_indexing disabled", [?MODULE]),
couch_views_jobs:set_timeout(),
{ok, {flags(), []}}.
diff --git a/src/couch_views/src/couch_views_updater.erl b/src/couch_views/src/couch_views_updater.erl
index c7d3146..f88c5a2 100644
--- a/src/couch_views/src/couch_views_updater.erl
+++ b/src/couch_views/src/couch_views_updater.erl
@@ -18,6 +18,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("couch_views/include/couch_views.hrl").
+-include_lib("kernel/include/logger.hrl").
% If the doc revision doesn't not match the NewRevId passed here we can ignore
% the document since it is then a conflict document and it doesn't need
@@ -33,11 +34,25 @@ index(Db, #doc{id = Id, revs = Revs} = Doc, _NewWinner, _OldWinner, NewRevId,
catch
error:{erlfdb_error, ErrCode}:Stack when is_integer(ErrCode) ->
DbName = fabric2_db:name(Db),
+ ?LOG_ERROR(#{
+ what => mango_index_update,
+ status => erlfdb_error,
+ details => ErrCode,
+ db => DbName,
+ docid => Id
+ }),
couch_log:error("Mango index erlfdb error Db ~s Doc ~p ~p",
[DbName, Id, ErrCode]),
erlang:raise(error, {erlfdb_error, ErrCode}, Stack);
Error:Reason ->
DbName = fabric2_db:name(Db),
+ ?LOG_ERROR(#{
+ what => mango_index_update,
+ status => Error,
+ details => Reason,
+ db => DbName,
+ docid => Id
+ }),
couch_log:error("Mango index error for Db ~s Doc ~p ~p ~p",
[DbName, Id, Error, Reason])
end.
diff --git a/src/couch_views/src/couch_views_util.erl b/src/couch_views/src/couch_views_util.erl
index 287d4ba..63f5daa 100644
--- a/src/couch_views/src/couch_views_util.erl
+++ b/src/couch_views/src/couch_views_util.erl
@@ -30,6 +30,7 @@
-include_lib("couch/include/couch_db.hrl").
-include("couch_views.hrl").
+-include_lib("kernel/include/logger.hrl").
ddoc_to_mrst(DbName, #doc{id=Id, body={Fields}}) ->
@@ -56,6 +57,12 @@ ddoc_to_mrst(DbName, #doc{id=Id, body={Fields}}) ->
DictBySrcAcc
end;
({Name, Else}, DictBySrcAcc) ->
+ ?LOG_ERROR(#{
+ what => invalid_view_definition,
+ db => DbName,
+ ddoc => Id,
+ view => Name
+ }),
couch_log:error("design_doc_to_view_group ~s views ~p",
[Name, Else]),
DictBySrcAcc
diff --git a/src/ctrace/src/ctrace.erl b/src/ctrace/src/ctrace.erl
index a890bde..2821352 100644
--- a/src/ctrace/src/ctrace.erl
+++ b/src/ctrace/src/ctrace.erl
@@ -44,6 +44,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("passage/include/opentracing.hrl").
-include("ctrace.hrl").
+-include_lib("kernel/include/logger.hrl").
-type operation()
diff --git a/src/ctrace/src/ctrace_config.erl b/src/ctrace/src/ctrace_config.erl
index c63c77f..e9141d2 100644
--- a/src/ctrace/src/ctrace_config.erl
+++ b/src/ctrace/src/ctrace_config.erl
@@ -29,6 +29,7 @@
]).
-include("ctrace.hrl").
+-include_lib("kernel/include/logger.hrl").
-spec is_enabled() -> boolean().
@@ -132,10 +133,12 @@ http_client(Endpoint, Method, Headers, Body, _ReporterOptions) ->
compile_filter(OperationId, FilterDef) ->
try
+ ?LOG_INFO(#{what => compile_filter, id => OperationId}),
couch_log:info("Compiling filter : ~s", [OperationId]),
ctrace_dsl:compile(OperationId, FilterDef),
true
catch throw:{error, Reason} ->
+ ?LOG_ERROR(#{what => compile_filter, id => OperationId, details => Reason}),
couch_log:error("Cannot compile ~s :: ~s~n", [OperationId, Reason]),
false
end.
diff --git a/src/ctrace/test/ctrace_config_test.erl b/src/ctrace/test/ctrace_config_test.erl
index 0827013..bc108b2 100644
--- a/src/ctrace/test/ctrace_config_test.erl
+++ b/src/ctrace/test/ctrace_config_test.erl
@@ -14,6 +14,7 @@
-include_lib("eunit/include/eunit.hrl").
-include_lib("ctrace/src/ctrace.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(TDEF(A), {atom_to_list(A), fun A/0}).
@@ -79,6 +80,7 @@ ensure_all_supported() ->
handle_all_syntax_error_supported() ->
+ ?LOG_ERROR(#{what => xkcd, event => test_start}),
couch_log:error("XKCD: TEST START", []),
config:delete("tracing.filters", "all", false),
test_util:wait_value(fun() ->
@@ -96,6 +98,7 @@ handle_all_syntax_error_supported() ->
% then we default to not generating traces
?assertEqual(false, ctrace:match(bam, #{gee => whiz})),
+ ?LOG_ERROR(#{what => xkcd, event => test_end}),
couch_log:error("XKCD: TEST END", []),
config:delete("tracing.filters", "all", false).
diff --git a/src/fabric/src/fabric2_db.erl b/src/fabric/src/fabric2_db.erl
index 0074865..91baa27 100644
--- a/src/fabric/src/fabric2_db.erl
+++ b/src/fabric/src/fabric2_db.erl
@@ -139,6 +139,7 @@
-include_lib("couch/include/couch_db.hrl").
-include("fabric2.hrl").
+-include_lib("kernel/include/logger.hrl").
% Default max database name length is based on CouchDb < 4.x compatibility. See
@@ -850,6 +851,7 @@ validate_docid(Id) when is_binary(Id) ->
_Else -> ok
end;
validate_docid(Id) ->
+ ?LOG_DEBUG(#{what => illegal_docid, docid => Id}),
couch_log:debug("Document id is not a string: ~p", [Id]),
throw({illegal_docid, <<"Document id must be a string">>}).
diff --git a/src/fabric/src/fabric2_db_expiration.erl b/src/fabric/src/fabric2_db_expiration.erl
index b438591..b8a063c 100644
--- a/src/fabric/src/fabric2_db_expiration.erl
+++ b/src/fabric/src/fabric2_db_expiration.erl
@@ -34,6 +34,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("fabric/include/fabric2.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(JOB_TYPE, <<"db_expiration">>).
-define(JOB_ID, <<"db_expiration_job">>).
@@ -81,7 +82,9 @@ handle_info(timeout, #st{job = undefined} = St) ->
handle_info({'EXIT', Pid, Exit}, #st{job = Pid} = St) ->
case Exit of
normal -> ok;
- Error -> couch_log:error("~p : job error ~p", [?MODULE, Error])
+ Error ->
+ ?LOG_ERROR(#{what => job_error, details => Error}),
+ couch_log:error("~p : job error ~p", [?MODULE, Error])
end,
NewPid = spawn_link(?MODULE, cleanup, [is_enabled()]),
{noreply, St#st{job = NewPid}};
@@ -132,6 +135,11 @@ cleanup(true) ->
ok = resubmit_job(Job1, Data1, schedule_sec())
catch
_Tag:Error:Stack ->
+ ?LOG_ERROR(#{
+ what => process_expirations_error,
+ job => Job,
+ details => Error
+ }),
couch_log:error("~p : processing error ~p ~p ~p",
[?MODULE, Job, Error, Stack]),
ok = resubmit_job(Job, Data, ?ERROR_RESCHEDULE_SEC),
@@ -179,6 +187,11 @@ process_row(DbInfo) ->
Since = Now - Retention,
case Since >= timestamp_to_sec(TimeStamp) of
true ->
+ ?LOG_NOTICE(#{
+ what => expire_db,
+ db => DbName,
+ deleted_at => TimeStamp
+ }),
couch_log:notice("Permanently deleting ~s database with"
" timestamp ~s", [DbName, TimeStamp]),
ok = fabric2_db:delete(DbName, [{deleted_at, TimeStamp}]);
diff --git a/src/fabric/src/fabric2_index.erl b/src/fabric/src/fabric2_index.erl
index 037f0f5..8d52e8b 100644
--- a/src/fabric/src/fabric2_index.erl
+++ b/src/fabric/src/fabric2_index.erl
@@ -34,6 +34,7 @@
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-callback build_indices(Db :: map(), DDocs :: list(#doc{})) ->
@@ -69,6 +70,13 @@ cleanup(Db) ->
ok;
Tag:Reason:Stack ->
DbName = fabric2_db:name(Db),
+ ?LOG_ERROR(#{
+ what => index_cleanup_failure,
+ db => DbName,
+ tag => Tag,
+ details => Reason,
+ stacktrace => Stack
+ }),
LogMsg = "~p failed to cleanup indices for `~s` ~p:~p ~p",
couch_log:error(LogMsg, [?MODULE, DbName, Tag, Reason, Stack])
end.
@@ -168,6 +176,13 @@ process_updates_iter([Db | Rest], Cont) ->
error:database_does_not_exist ->
ok;
Tag:Reason:Stack ->
+ ?LOG_ERROR(#{
+ what => index_build_failure,
+ db => Db,
+ tag => Tag,
+ details => Reason,
+ stacktrace => Stack
+ }),
LogMsg = "~p failed to build indices for `~s` ~p:~p ~p",
couch_log:error(LogMsg, [?MODULE, Db, Tag, Reason, Stack])
end,
diff --git a/src/fabric/src/fabric2_server.erl b/src/fabric/src/fabric2_server.erl
index e427f20..c68ff88 100644
--- a/src/fabric/src/fabric2_server.erl
+++ b/src/fabric/src/fabric2_server.erl
@@ -43,6 +43,7 @@
-include_lib("couch/include/couch_db.hrl").
-include_lib("kernel/include/file.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(CLUSTER_FILE_MACOS, "/usr/local/etc/foundationdb/fdb.cluster").
-define(CLUSTER_FILE_LINUX, "/etc/foundationdb/fdb.cluster").
@@ -254,14 +255,25 @@ find_cluster_file([{custom, undefined} | Rest]) ->
find_cluster_file(Rest);
find_cluster_file([{Type, Location} | Rest]) ->
+ Msg = #{
+ in => fdb_connection_setup,
+ configuration_type => Type,
+ cluster_file => Location
+ },
case file:read_file_info(Location, [posix]) of
{ok, #file_info{access = read_write}} ->
+ ?LOG_INFO(maps:merge(Msg, #{status => ok})),
couch_log:info(
"Using ~s FDB cluster file: ~s",
[Type, Location]
),
{ok, Location};
{ok, #file_info{access = read}} ->
+ ?LOG_WARNING(maps:merge(Msg, #{
+ status => read_only_file,
+ details => "If coordinators are changed without updating this "
+ "file CouchDB may be unable to connect to the FDB cluster!"
+ })),
couch_log:warning(
"Using read-only ~s FDB cluster file: ~s -- if coordinators "
"are changed without updating this file CouchDB may be unable "
@@ -270,24 +282,31 @@ find_cluster_file([{Type, Location} | Rest]) ->
),
{ok, Location};
{ok, _} ->
+ ?LOG_ERROR(maps:merge(Msg, #{
+ status => permissions_error,
+ details => "CouchDB needs read/write access to FDB cluster file"
+ })),
couch_log:error(
"CouchDB needs read/write access to FDB cluster file: ~s",
[Location]
),
{error, cluster_file_permissions};
{error, Reason} when Type =:= custom ->
+ ?LOG_ERROR(maps:merge(Msg, #{status => Reason})),
couch_log:error(
"Encountered ~p error looking for FDB cluster file: ~s",
[Reason, Location]
),
{error, Reason};
{error, enoent} when Type =:= default ->
+ ?LOG_INFO(maps:merge(Msg, #{status => enoent})),
couch_log:info(
"No FDB cluster file found at ~s",
[Location]
),
find_cluster_file(Rest);
{error, Reason} when Type =:= default ->
+ ?LOG_WARNING(maps:merge(Msg, #{status => Reason})),
couch_log:warning(
"Encountered ~p error looking for FDB cluster file: ~s",
[Reason, Location]
@@ -315,6 +334,11 @@ apply_tx_option(Db, Option, Val, integer) ->
set_option(Db, Option, list_to_integer(Val))
catch
error:badarg ->
+ ?LOG_ERROR(#{
+ what => invalid_transaction_option_value,
+ option => Option,
+ value => Val
+ }),
Msg = "~p : Invalid integer tx option ~p = ~p",
couch_log:error(Msg, [?MODULE, Option, Val])
end;
@@ -325,6 +349,12 @@ apply_tx_option(Db, Option, Val, binary) ->
true ->
set_option(Db, Option, BinVal);
false ->
+ ?LOG_ERROR(#{
+ what => invalid_transaction_option_value,
+ option => Option,
+ value => Val,
+ details => "string transaction option must be less than 16 bytes"
+ }),
Msg = "~p : String tx option ~p is larger than 16 bytes",
couch_log:error(Msg, [?MODULE, Option])
end.
@@ -337,6 +367,11 @@ set_option(Db, Option, Val) ->
% This could happen if the option is not supported by erlfdb or
% fdbsever.
error:badarg ->
+ ?LOG_ERROR(#{
+ what => transaction_option_error,
+ option => Option,
+ value => Val
+ }),
Msg = "~p : Could not set fdb tx option ~p = ~p",
couch_log:error(Msg, [?MODULE, Option, Val])
end.
diff --git a/src/fabric/src/fabric2_users_db.erl b/src/fabric/src/fabric2_users_db.erl
index 9a8a462..fdc787a 100644
--- a/src/fabric/src/fabric2_users_db.erl
+++ b/src/fabric/src/fabric2_users_db.erl
@@ -19,6 +19,7 @@
]).
-include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(NAME, <<"name">>).
-define(PASSWORD, <<"password">>).
@@ -94,6 +95,13 @@ save_doc(#doc{body={Body}} = Doc) ->
Body4 = proplists:delete(?PASSWORD, Body3),
Doc#doc{body={Body4}};
{_ClearPassword, Scheme} ->
+ ?LOG_ERROR(#{
+ what => invalid_config_setting,
+ section => couch_httpd_auth,
+ key => password_scheme,
+ value => Scheme,
+ details => "password_scheme must one of (simple, pbkdf2)"
+ }),
couch_log:error("[couch_httpd_auth] password_scheme value of '~p' is invalid.", [Scheme]),
throw({forbidden, "Server cannot hash passwords at this time."})
end.
diff --git a/src/mango/src/mango_cursor_view.erl b/src/mango/src/mango_cursor_view.erl
index 992e9cf..4a22e15 100644
--- a/src/mango/src/mango_cursor_view.erl
+++ b/src/mango/src/mango_cursor_view.erl
@@ -30,6 +30,7 @@
-include_lib("couch_views/include/couch_views.hrl").
-include("mango_cursor.hrl").
-include("mango_idx_view.hrl").
+-include_lib("kernel/include/logger.hrl").
create(Db, Indexes, Selector, Opts) ->
@@ -241,6 +242,7 @@ handle_message({row, Props}, Cursor) ->
},
{ok, Cursor1};
Error ->
+ ?LOG_ERROR(#{what => load_doc_failure, details => Error}),
couch_log:error("~s :: Error loading doc: ~p", [?MODULE, Error]),
{ok, Cursor}
end;
diff --git a/src/mango/src/mango_idx_view.erl b/src/mango/src/mango_idx_view.erl
index a73d82a..35b741a 100644
--- a/src/mango/src/mango_idx_view.erl
+++ b/src/mango/src/mango_idx_view.erl
@@ -35,6 +35,7 @@
-include("mango.hrl").
-include("mango_idx.hrl").
-include("mango_idx_view.hrl").
+-include_lib("kernel/include/logger.hrl").
validate_new(#idx{}=Idx, _Db) ->
@@ -254,6 +255,12 @@ validate_ddoc(VProps) ->
Opts = lists:keydelete(<<"sort">>, 1, Opts0),
{Def, Opts}
catch Error:Reason ->
+ ?LOG_ERROR(#{
+ what => invalid_index_definition,
+ tag => Error,
+ details => Reason,
+ index => VProps
+ }),
couch_log:error("Invalid Index Def ~p. Error: ~p, Reason: ~p",
[VProps, Error, Reason]),
invalid_view