diff options
Diffstat (limited to 'src')
54 files changed, 999 insertions, 118 deletions
diff --git a/src/aegis/src/aegis_server.erl b/src/aegis/src/aegis_server.erl index 15fea4c63..92ba7e80d 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 135c4ec0b..55a47c902 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 c5a56bddb..88ffb7ade 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 a8dd348f8..ba1323387 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 8f08c7fe1..4a7b631f9 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 43631c058..d46875d75 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 ae1efa486..18622783c 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 8b51e6c40..250690d51 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 01dc0f4a1..22890895a 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 f2ff2ac24..002facd48 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 104a48257..883fe38e8 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 7d728e647..b7402202d 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 33795a3a1..7e6e7d6c9 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 574dba9c8..3d6b4da01 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 6a0322c73..4627a9fd9 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 6e7ef98b7..7a1afae8b 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 ed7df1123..63fabfdde 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 fe37a7c00..ebc97b926 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 74c432e25..9c0c89972 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 3ceece008..5cebcf946 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 37faf907a..b47834f2f 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 2a080e94f..afa1fba7a 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 d5ed3f94f..8add3d5f2 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 883bc8f73..4ff01e74b 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 4b3354d6e..0f55cedb9 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 80ceb3d79..7dbacc633 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 a690d37c3..a0c6d2b8a 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 17e5bf2d6..fd592a87f 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 a59c770b4..2f47fd60a 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 6adf1af5e..97c728971 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 f31baf41d..ace93d545 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 f84d1299a..d70ad1cc0 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 52baa3915..28b0f3811 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 d11bdb738..951471a14 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 a2e90b061..2452a222d 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 79c778d23..ac25bee41 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 4cd984c1a..b57727f98 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 2164a5827..7f0e2d5f2 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 71a4abb8d..e94eaf170 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 94531893d..ee32d4e9f 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 7c96bb8bb..f88c5a23d 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 287d4bad6..63f5daafc 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 8ae51c487..2821352bf 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 c63c77f1b..e9141d21a 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 0827013fd..bc108b2a1 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 a5de00ca0..d4f15c5b0 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 94cb61b82..b8a063c08 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 3c59cd7e2..8d52e8b19 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 8a4a8d8df..0da2b79e9 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 9a8a462c3..fdc787a02 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 f95e410c6..cd22778ef 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 992e9cf7d..4a22e15fa 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 9ac4dfc88..0d035dd99 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 a73d82ae6..35b741a49 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 |