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/30 17:56:45 UTC
[couchdb] branch main updated: Add structured logging reports via
new Erlang 21 logger (#3526)
This is an automated email from the ASF dual-hosted git repository.
kocolosk pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/couchdb.git
The following commit(s) were added to refs/heads/main by this push:
new 720393b Add structured logging reports via new Erlang 21 logger (#3526)
720393b is described below
commit 720393b4961f0a14742a39304a7f04415aef1aa8
Author: Adam Kocoloski <ko...@apache.org>
AuthorDate: Fri Apr 30 13:56:14 2021 -0400
Add structured logging reports via new Erlang 21 logger (#3526)
* Drop support for Erlang < 21
The new logger only works in Erlang 21+, so we can start simplifying
the codebase by removing the macro that provides support for retrieving
stack traces the old way.
* Produce structured logging reports
We use the new logger macros to generate log events alongside the
existing couch_log system. This commit does not introduce any handlers
for the new events; that will come later.
---
build-aux/Jenkinsfile.full | 26 ++--
build-aux/Jenkinsfile.pr | 4 +-
rebar.config.script | 2 +-
src/aegis/src/aegis_server.erl | 3 +
src/chttpd/src/chttpd.erl | 61 +++++++-
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 | 9 +-
src/chttpd/src/chttpd_stats.erl | 13 +-
src/chttpd/src/chttpd_sup.erl | 10 ++
src/couch/include/couch_db.hrl | 24 ---
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 | 3 +-
src/couch/src/couch_sup.erl | 34 ++++-
src/couch/test/eunit/couch_flags_config_tests.erl | 6 +-
.../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 | 15 ++
src/couch_js/src/couch_js_native_process.erl | 40 ++++-
src/couch_js/src/couch_js_os_process.erl | 65 ++++++++
src/couch_js/src/couch_js_proc_manager.erl | 10 +-
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 | 170 ++++++++++++++++++---
.../src/couch_replicator_job_server.erl | 33 ++++
.../src/couch_replicator_parse.erl | 36 ++++-
.../src/couch_replicator_worker.erl | 94 +++++++++++-
src/couch_views/src/couch_views_indexer.erl | 19 ++-
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 | 17 ++-
src/couch_views/src/couch_views_util.erl | 7 +
src/ctrace/src/ctrace.erl | 3 +-
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 | 17 ++-
src/fabric/src/fabric2_index.erl | 19 ++-
src/fabric/src/fabric2_server.erl | 44 ++++++
src/fabric/src/fabric2_users_db.erl | 8 +
src/fabric/src/fabric2_util.erl | 2 +-
src/mango/src/mango_cursor_view.erl | 2 +
src/mango/src/mango_httpd.erl | 2 +-
src/mango/src/mango_idx_view.erl | 7 +
57 files changed, 1015 insertions(+), 134 deletions(-)
diff --git a/build-aux/Jenkinsfile.full b/build-aux/Jenkinsfile.full
index 7fd6e5c..9b64745 100644
--- a/build-aux/Jenkinsfile.full
+++ b/build-aux/Jenkinsfile.full
@@ -81,7 +81,7 @@ pipeline {
agent {
docker {
label 'docker'
- image 'apache/couchdbci-debian:buster-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-debian:buster-erlang-21.3.8.17-1'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
registryCredentialsId 'dockerhub_creds'
@@ -199,7 +199,7 @@ pipeline {
stage('CentOS 7') {
agent {
docker {
- image 'apache/couchdbci-centos:7-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-centos:7-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -245,7 +245,7 @@ pipeline {
stage('CentOS 8') {
agent {
docker {
- image 'apache/couchdbci-centos:8-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-centos:8-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -291,7 +291,7 @@ pipeline {
stage('Ubuntu Xenial') {
agent {
docker {
- image 'apache/couchdbci-ubuntu:xenial-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-ubuntu:xenial-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -336,7 +336,7 @@ pipeline {
stage('Ubuntu Bionic') {
agent {
docker {
- image 'apache/couchdbci-ubuntu:bionic-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-ubuntu:bionic-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -381,7 +381,7 @@ pipeline {
stage('Ubuntu Focal') {
agent {
docker {
- image 'apache/couchdbci-ubuntu:focal-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-ubuntu:focal-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -426,7 +426,7 @@ pipeline {
stage('Debian Stretch') {
agent {
docker {
- image 'apache/couchdbci-debian:stretch-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-debian:stretch-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -471,7 +471,7 @@ pipeline {
stage('Debian Buster amd64') {
agent {
docker {
- image 'apache/couchdbci-debian:buster-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-debian:buster-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -517,7 +517,7 @@ pipeline {
when { expression { return false } }
agent {
docker {
- image 'apache/couchdbci-debian:arm64v8-buster-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-debian:arm64v8-buster-erlang-21.3.8.17-1'
label 'arm64v8'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
@@ -566,7 +566,7 @@ pipeline {
// stage('Debian Buster ppc64le') {
// agent {
// docker {
-// image 'apache/couchdbci-debian:ppc64le-buster-erlang-20.3.8.26-1'
+// image 'apache/couchdbci-debian:ppc64le-buster-erlang-21.3.8.17-1'
// label 'ppc64le'
// args "${DOCKER_ARGS}"
// registryUrl 'https://docker.io/'
@@ -636,12 +636,12 @@ pipeline {
}
stage('Pull latest docker image') {
steps {
- sh "docker pull apache/couchdbci-debian:arm64v8-buster-erlang-20.3.8.26-1"
+ sh "docker pull apache/couchdbci-debian:arm64v8-buster-erlang-21.3.8.17-1"
}
}
stage('Build from tarball & test & packages') {
steps {
- withDockerContainer(image: "apache/couchdbci-debian:arm64v8-buster-erlang-20.3.8.26-1", args: "${DOCKER_ARGS}") {
+ withDockerContainer(image: "apache/couchdbci-debian:arm64v8-buster-erlang-21.3.8.17-1", args: "${DOCKER_ARGS}") {
unstash 'tarball'
withEnv(['MIX_HOME='+pwd(), 'HEX_HOME='+pwd()]) {
sh( script: build_and_test )
@@ -681,7 +681,7 @@ pipeline {
agent {
docker {
- image 'apache/couchdbci-debian:buster-erlang-20.3.8.26-1'
+ image 'apache/couchdbci-debian:buster-erlang-21.3.8.17-1'
label 'docker'
args "${DOCKER_ARGS}"
registryUrl 'https://docker.io/'
diff --git a/build-aux/Jenkinsfile.pr b/build-aux/Jenkinsfile.pr
index 8f9d6f1..77362b1 100644
--- a/build-aux/Jenkinsfile.pr
+++ b/build-aux/Jenkinsfile.pr
@@ -50,7 +50,7 @@ pipeline {
// Search for ERLANG_VERSION
// see https://issues.jenkins.io/browse/JENKINS-61047 for why this cannot
// be done parametrically
- LOW_ERLANG_VER = '20.3.8.26'
+ LOW_ERLANG_VER = '21.3.8.22'
}
options {
@@ -107,7 +107,7 @@ pipeline {
axes {
axis {
name 'ERLANG_VERSION'
- values '20.3.8.26', '21.3.8.22', '22.3.4.17', '23.3.1'
+ values '21.3.8.22', '22.3.4.17', '23.3.1'
}
}
diff --git a/rebar.config.script b/rebar.config.script
index e61b5aa..789c42d 100644
--- a/rebar.config.script
+++ b/rebar.config.script
@@ -192,7 +192,7 @@ ErlOpts = case os:getenv("ERL_OPTS") of
end.
AddConfig = [
- {require_otp_vsn, "20|21|22|23"},
+ {require_otp_vsn, "21|22|23"},
{deps_dir, "src"},
{deps, lists:map(MakeDep, DepDescs ++ OptionalDeps)},
{sub_dirs, SubDirs},
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/src/chttpd.erl b/src/chttpd/src/chttpd.erl
index 135c4ec..55a47c9 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.
@@ -223,6 +230,7 @@ handle_request_int(MochiReq) ->
end,
Nonce = couch_util:to_hex(crypto:strong_rand_bytes(5)),
+ logger:set_process_metadata(#{request_id => Nonce}),
HttpReq0 = #httpd{
mochi_req = MochiReq,
@@ -268,6 +276,10 @@ handle_request_int(MochiReq) ->
span_ok(HttpResp),
{ok, Resp};
#httpd_resp{status = aborted, reason = Reason} ->
+ ?LOG_ERROR(#{
+ what => abnormal_response_termation,
+ details => Reason
+ }),
couch_log:error("Response abnormally terminated: ~p", [Reason]),
exit(normal)
end.
@@ -278,7 +290,7 @@ before_request(HttpReq) ->
{ok, HttpReq1} = chttpd_plugin:before_request(HttpReq),
chttpd_stats:init(HttpReq1),
{ok, HttpReq1}
- catch ?STACKTRACE(Tag, Error, Stack)
+ catch Tag:Error:Stack ->
{error, catch_error(HttpReq, Tag, Error, Stack)}
end.
@@ -286,7 +298,7 @@ after_request(HttpReq, HttpResp0) ->
{ok, HttpResp1} =
try
chttpd_plugin:after_request(HttpReq, HttpResp0)
- catch ?STACKTRACE(_Tag, Error, Stack)
+ catch _Tag:Error:Stack ->
send_error(HttpReq, {Error, nil, Stack}),
{ok, HttpResp0#httpd_resp{status = aborted}}
end,
@@ -319,7 +331,7 @@ process_request(#httpd{mochi_req = MochiReq} = HttpReq) ->
Response ->
{HttpReq, Response}
end
- catch ?STACKTRACE(Tag, Error, Stack)
+ catch Tag:Error:Stack ->
{HttpReq, catch_error(HttpReq, Tag, Error, Stack)}
end.
@@ -332,7 +344,7 @@ handle_req_after_auth(HandlerKey, HttpReq) ->
AuthorizedReq = chttpd_auth:authorize(possibly_hack(HttpReq),
fun chttpd_auth_request:authorize_request/1),
{AuthorizedReq, HandlerFun(AuthorizedReq)}
- catch ?STACKTRACE(Tag, Error, Stack)
+ catch Tag:Error:Stack ->
{HttpReq, catch_error(HttpReq, Tag, Error, Stack)}
end.
@@ -348,6 +360,13 @@ catch_error(HttpReq, exit, {mochiweb_recv_error, E}, _Stack) ->
peer = Peer,
original_method = Method
} = HttpReq,
+ ?LOG_NOTICE(#{
+ what => mochiweb_recv_error,
+ 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 +432,23 @@ 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,
+ 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 +1279,13 @@ 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,
+ 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 +1436,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 43631c0..d46875d 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
@@ -44,7 +45,13 @@ handler_info(HttpReq) ->
Default = {'unknown.unknown', #{}},
try
select(collect(handler_info, [Method, PathParts, HttpReq]), Default)
- catch ?STACKTRACE(Type, Reason, Stack)
+ catch Type:Reason:Stack ->
+ ?LOG_ERROR(#{
+ what => handler_info_failure,
+ 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 ae1efa4..1862278 100644
--- a/src/chttpd/src/chttpd_stats.erl
+++ b/src/chttpd/src/chttpd_stats.erl
@@ -12,8 +12,7 @@
-module(chttpd_stats).
-% for the stacktrace macro only so far
--include_lib("couch/include/couch_db.hrl").
+-include_lib("kernel/include/logger.hrl").
-export([
init/1,
@@ -63,13 +62,19 @@ report(HttpResp) ->
_ ->
ok
end
- catch ?STACKTRACE(T, R, S)
+ 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..250690d 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 non-negative 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/include/couch_db.hrl b/src/couch/include/couch_db.hrl
index 01dc0f4..2289089 100644
--- a/src/couch/include/couch_db.hrl
+++ b/src/couch/include/couch_db.hrl
@@ -178,27 +178,3 @@
-define(record_to_keyval(Name, Record),
lists:zip(record_info(fields, Name), tl(tuple_to_list(Record)))).
-
-%% Erlang/OTP 21 deprecates and 23 removes get_stacktrace(), so
-%% we have to monkey around until we can drop support < 21.
-%% h/t https://github.com/erlang/otp/pull/1783#issuecomment-386190970
-
-%% use like so:
-% try function1(Arg1)
-% catch
-% ?STACKTRACE(exit, badarg, ErrorStackTrace)
-% % do stuff with ErrorStackTrace
-% % ...
-% end,
-
-% Get the stacktrace in a way that is backwards compatible
-% OTP_RELEASE is only available in OTP 21 and later, so we don’t need
-% to do any other version magic here.
--ifdef(OTP_RELEASE).
--define(STACKTRACE(ErrorType, Error, Stack),
- ErrorType:Error:Stack ->).
--else.
--define(STACKTRACE(ErrorType, Error, Stack),
- ErrorType:Error ->
- Stack = erlang:get_stacktrace(),).
--endif.
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 6a0322c..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).
@@ -321,7 +322,7 @@ find_proc(#client{lang = Lang, ddoc = DDoc, ddoc_key = DDocKey} = Client) ->
find_proc(Lang, Fun) ->
try iter_procs(Lang, Fun)
- catch ?STACKTRACE(error, Reason, StackTrace)
+ catch error:Reason:StackTrace ->
couch_log:error("~p ~p ~p", [?MODULE, Reason, StackTrace]),
{error, Reason}
end.
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/test/eunit/couch_flags_config_tests.erl b/src/couch/test/eunit/couch_flags_config_tests.erl
index ed7df11..63fabfd 100644
--- a/src/couch/test/eunit/couch_flags_config_tests.erl
+++ b/src/couch/test/eunit/couch_flags_config_tests.erl
@@ -98,10 +98,8 @@ test_config() ->
parse_flags_term_test_() ->
LongBinary = binary:copy(<<"a">>, ?MAX_FLAG_NAME_LENGTH + 1),
- ExpectedError = {error, {"Cannot parse list of tags: ~n~p",
- [{too_long, LongBinary}]}},
- ExpectedUnknownError = {error,{"Cannot parse list of tags: ~n~p",
- [{invalid_flag,<<"dddddddd">>}]}},
+ ExpectedError = {error, [{too_long, LongBinary}]},
+ ExpectedUnknownError = {error, [{invalid_flag,<<"dddddddd">>}]},
[
{"empty binary", ?_assertEqual(
[], couch_flags_config:parse_flags_term(<<>>))},
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 3ceece0..5cebcf9 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, {
@@ -81,6 +82,12 @@ handle_info(check_activity, St) ->
check_activity(St)
catch
error:{Tag, Err} when ?COUCH_JOBS_RETRYABLE(Tag, Err) ->
+ ?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
@@ -91,6 +98,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 37faf90..b47834f 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").
@@ -125,6 +126,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 2a080e9..afa1fba 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").
-include("couch_jobs.hrl").
@@ -95,6 +96,11 @@ handle_info(check_types, St) ->
{noreply, St};
handle_info({'DOWN', _Ref, process, Pid, Reason}, St) ->
+ ?LOG_ERROR(#{
+ what => monitored_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};
@@ -102,6 +108,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};
@@ -174,6 +184,11 @@ fdb_types() ->
end)
catch
error:{Tag, Err} when ?COUCH_JOBS_RETRYABLE(Tag, Err) ->
+ ?LOG_WARNING(#{
+ what => fdb_connection_error,
+ tag => Tag,
+ details => Err
+ }),
LogMsg = "~p : Error ~p:~p connecting to FDB",
couch_log:warning(LogMsg, [?MODULE, Tag, Err]),
[]
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..4ff01e7 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,25 @@ 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,
+ tag => Id,
+ 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 +195,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 +253,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 +268,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 +281,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 4b3354d..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] ->
@@ -320,7 +323,12 @@ find_proc(#client{lang = Lang, ddoc = DDoc, ddoc_key = DDocKey} = Client) ->
find_proc(Lang, Fun) ->
try iter_procs(Lang, Fun)
- catch ?STACKTRACE(error, Reason, StackTrace)
+ 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..fd592a8 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_sec => 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..2f47fd6 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_message, 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..97c7289 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(LogMsg#{delay_sec => 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..d70ad1c 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_sec => 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..28b0f38 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_sec => 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 d11bdb7..951471a 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"
@@ -221,11 +267,9 @@ handle_info(timeout, delayed_init) ->
{ok, State} -> {noreply, State};
{stop, Reason, State} -> {stop, Reason, State}
catch
- ?STACKTRACE(exit, {shutdown, finished}, Stack)
- {stop, {shutdown, finished}, {init_error, Stack}};
- ?STACKTRACE(exit, {shtudown, halt}, Stack)
- {stop, {shutdown, halt}, {init_error, Stack}};
- ?STACKTRACE(_Tag, Error, Stack)
+ exit:{shutdown, Exit}:Stack when Exit =:= finished orelse Exit =:= halt ->
+ {stop, {shutdown, Exit}, {init_error, Stack}};
+ _Tag:Error:Stack ->
ShutdownReason = {error, replication_start_error(Error)},
{stop, {shutdown, ShutdownReason}, {init_error, Stack}}
end;
@@ -253,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};
@@ -275,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)};
@@ -283,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)};
@@ -291,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)};
@@ -299,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 => linked_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}};
@@ -321,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}
@@ -329,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};
@@ -406,15 +472,19 @@ delayed_init() ->
try do_init(Job, JobData) of
State = #rep_state{} -> {ok, State}
catch
- ?STACKTRACE(exit, {http_request_failed, _, _, max_backoff}, Stack)
+ exit:{http_request_failed, _, _, max_backoff}:Stack ->
reschedule_on_error(undefined, Job, JobData, max_backoff),
{stop, {shutdown, max_backoff}, {init_error, Stack}};
- ?STACKTRACE(exit, {shutdown, finished}, Stack)
- {stop, {shutdown, finished}, {init_error, Stack}};
- ?STACKTRACE(exit, {shutdown, halt}, Stack)
- {stop, {shutdown, halt}, {init_error, Stack}};
- ?STACKTRACE(_Tag, Error, Stack)
+ exit:{shutdown, Exit}:Stack when Exit =:= finished orelse Exit =:= halt ->
+ {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),
@@ -575,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),
@@ -865,6 +948,12 @@ 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,
+ replication_id => RepId,
+ 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};
@@ -964,7 +1053,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),
@@ -1047,6 +1150,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 ->
@@ -1115,6 +1225,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),
@@ -1275,7 +1392,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, []),
@@ -1283,7 +1400,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.
@@ -1430,6 +1548,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]).
@@ -1446,6 +1575,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 79c778d..ac25bee 100644
--- a/src/couch_replicator/src/couch_replicator_parse.erl
+++ b/src/couch_replicator/src/couch_replicator_parse.erl
@@ -22,8 +22,8 @@
-include_lib("ibrowse/include/ibrowse.hrl").
--include_lib("couch/include/couch_db.hrl").
-include("couch_replicator.hrl").
+-include_lib("kernel/include/logger.hrl").
-define(DEFAULT_SOCK_OPTS, "[{keepalive, true}, {nodelay, false}]").
@@ -60,11 +60,24 @@ parse_rep_doc(RepDoc) ->
{ok, Rep} = try
parse_rep(RepDoc, null)
catch
- ?STACKTRACE(throw, {error, Reason}, Stack)
+ 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});
- ?STACKTRACE(Tag, Err, Stack)
+ 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,11 +95,24 @@ parse_transient_rep(#{} = Body, UserName) ->
{ok, Rep} = try
parse_rep(Body, UserName)
catch
- ?STACKTRACE(throw, {error, Reason}, Stack)
+ 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});
- ?STACKTRACE(Tag, Err, Stack)
+ 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..b57727f 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_sec => 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_sec => 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_bytes => 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_bytes => 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_bytes => 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 2164a58..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).
@@ -121,7 +122,15 @@ init() ->
ok;
error:database_does_not_exist ->
fail_job(Job, Data, db_deleted, "Database was deleted");
- ?STACKTRACE(Error, Reason, Stack)
+ 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 7c96bb8..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
@@ -31,13 +32,27 @@ index(Db, #doc{id = Id, revs = Revs} = Doc, _NewWinner, _OldWinner, NewRevId,
index_int(Db, Doc, Seq)
end
catch
- ?STACKTRACE(error, {erlfdb_error, ErrCode}, Stack)
+ 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 8ae51c4..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()
@@ -109,7 +110,7 @@ with_span(Operation, Options, Fun) ->
try
start_span(Operation, Options),
Fun()
- catch ?STACKTRACE(Type, Reason, Stack)
+ catch Type:Reason:Stack ->
log(#{
?LOG_FIELD_ERROR_KIND => Type,
?LOG_FIELD_MESSAGE => Reason,
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 a5de00c..d4f15c5 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
@@ -841,6 +842,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 94cb61b..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}};
@@ -131,7 +134,12 @@ cleanup(true) ->
{ok, Job1, Data1} = ?MODULE:process_expirations(Job, Data),
ok = resubmit_job(Job1, Data1, schedule_sec())
catch
- ?STACKTRACE(_Tag, Error, Stack)
+ _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 3c59cd7..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{})) ->
@@ -67,8 +68,15 @@ cleanup(Db) ->
catch
error:database_does_not_exist ->
ok;
- ?STACKTRACE(Tag, Reason, Stack)
+ 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.
@@ -167,7 +175,14 @@ process_updates_iter([Db | Rest], Cont) ->
catch
error:database_does_not_exist ->
ok;
- ?STACKTRACE(Tag, Reason, Stack)
+ 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 8a4a8d8..0da2b79 100644
--- a/src/fabric/src/fabric2_server.erl
+++ b/src/fabric/src/fabric2_server.erl
@@ -44,6 +44,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").
@@ -261,14 +262,25 @@ find_cluster_file([{custom, undefined} | Rest]) ->
find_cluster_file(Rest);
find_cluster_file([{Type, Location} | Rest]) ->
+ Msg = #{
+ what => 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(Msg#{status => ok}),
couch_log:info(
"Using ~s FDB cluster file: ~s",
[Type, Location]
),
{ok, Location};
{ok, #file_info{access = read}} ->
+ ?LOG_WARNING(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 "
@@ -277,24 +289,40 @@ find_cluster_file([{Type, Location} | Rest]) ->
),
{ok, Location};
{ok, _} ->
+ ?LOG_ERROR(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(Msg#{
+ status => Reason,
+ details => file:format_error(Reason)
+ }),
couch_log:error(
"Encountered ~p error looking for FDB cluster file: ~s",
[Reason, Location]
),
{error, Reason};
{error, enoent} when Type =:= default ->
+ ?LOG_INFO(Msg#{
+ status => enoent,
+ details => file:format_error(enoent)
+ }),
couch_log:info(
"No FDB cluster file found at ~s",
[Location]
),
find_cluster_file(Rest);
{error, Reason} when Type =:= default ->
+ ?LOG_WARNING(Msg#{
+ status => Reason,
+ details => file:format_error(Reason)
+ }),
couch_log:warning(
"Encountered ~p error looking for FDB cluster file: ~s",
[Reason, Location]
@@ -322,6 +350,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;
@@ -332,6 +365,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.
@@ -344,6 +383,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/fabric/src/fabric2_util.erl b/src/fabric/src/fabric2_util.erl
index f95e410..cd22778 100644
--- a/src/fabric/src/fabric2_util.erl
+++ b/src/fabric/src/fabric2_util.erl
@@ -386,6 +386,6 @@ pmap(Fun, Args, Opts) ->
pmap_exec(Fun, Arg) ->
try
{'$res', Fun(Arg)}
- catch ?STACKTRACE(Tag, Reason, Stack)
+ catch Tag:Reason:Stack ->
{'$err', Tag, Reason, Stack}
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_httpd.erl b/src/mango/src/mango_httpd.erl
index 9ac4dfc..0d035dd 100644
--- a/src/mango/src/mango_httpd.erl
+++ b/src/mango/src/mango_httpd.erl
@@ -36,7 +36,7 @@ handle_req(#httpd{} = Req, Db) ->
try
handle_req_int(Req, Db)
catch
- ?STACKTRACE(throw, {mango_error, Module, Reason}, Stack)
+ throw:{mango_error, Module, Reason}:Stack ->
case mango_error:info(Module, Reason) of
{500, ErrorStr, ReasonStr} ->
chttpd:send_error(Req, {ErrorStr, ReasonStr, Stack});
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