ReeceStevens opened a new issue #1093: Hanging or 500 errors during concurrent replication URL: https://github.com/apache/couchdb/issues/1093 ## Expected Behavior If multiple replications are occurring in different processes, they should not cause the database to return a 500 error (in the case of CouchDB 2.1.1) or hang for extended periods of time (CouchDB 1.6.1). ## Current Behavior I apologize in advance for the length of some of these log snippets-- I am including the entirety of lines that are beginning with `[error]`, which sometimes can be quite a bit of information. ### CouchDB 2.1.1 If multiple threads are triggering replications at the same time, an occasional server 500 error will occur. This is more likely to occur if all replications are referring to the same source database. Logs show the following message: ``` [error] 2018-01-05T18:34:27.007398Z [email protected] <0.14271.1667> f5fe1295eb req_err(54226069) internal_server_error : No DB shards could be opened. [<<"fabric_util:get_shard/4 L185">>,<<"fabric_util:get_shard/4 L200">>,<<"fabric_util:get_shard/4 L200">>,<<"fabric:get_security/2 L146">>,<<"chttpd_au th_request:db_authorization_check/1 L91">>,<<"chttpd_auth_request:authorize_request/1 L19">>,<<"chttpd:process_request/1 L293">>,<<"chttpd:handle_request_i nt/1 L231">>] [error] 2018-01-05T18:34:25.555735Z [email protected] <0.23659.1662> -------- Replicator, request GET to "http://localhost:5984/rs_src_6/60da00929026155788 ff550e81ccdabe?revs=true&open_revs=%5B%221-4d79096a94eeb4a5b15bc94cb52a07dc%22%5D&latest=true" failed. The received HTTP error code is 500 [notice] 2018-01-05T18:34:25.560581Z [email protected] <0.17111.1664> -------- Retrying GET to http://localhost:5984/rs_src_6/60da00929026155788ff550e81ccd abe?revs=true&open_revs=%5B%221-4d79096a94eeb4a5b15bc94cb52a07dc%22%5D&latest=true in 4.0 seconds due to error {code,500} ``` and occasionally: ``` [notice] 2018-01-05T19:36:46.773242Z [email protected] <0.3476.1676> 946d87022f localhost:5984 127.0.0.1 undefined PUT /rs_dest_4/_local/2ea4663317c5b7556$ 9098f53783083c 500 ok 2595 [error] 2018-01-05T19:36:46.773493Z [email protected] <0.28639.1669> -------- Replicator, request PUT to "http://localhost:5984/rs_dest_4/_local/2ea4663317 c5b755669098f53783083c" failed due to error {code,500} [error] 2018-01-05T19:36:46.773568Z [email protected] <0.28639.1669> -------- Replication `2ea4663317c5b755669098f53783083c+create_target` (`http://localho st:5984/rs_src_0/` -> `http://localhost:5984/rs_dest_4/`) failed: {http_request_failed,"PUT", "http://localhost:5984/rs_dest_4/_local/2ea4663317c5b755669098f53783083c";, {error,{code,500}}} [error] 2018-01-05T19:36:46.773790Z [email protected] <0.350.0> -------- couch_replicator_scheduler : Transient job {"2ea4663317c5b755669098f53783083c","+c reate_target"} failed, removing. Error: <<"{http_request_failed,\"PUT\",\n \"http://localhost:5984/rs_dest_4/_local/2ea4663317c5b755669 098f53783083c\",\n {error,{code,500}}}">> [notice] 2018-01-05T19:36:46.773990Z [email protected] <0.11718.1671> d2ce14ca71 localhost:5984 127.0.0.1 undefined POST /_replicate 500 ok 68552 [error] 2018-01-05T19:36:46.774397Z [email protected] <0.28639.1669> -------- gen_server {couch_replicator_scheduler_job,{[50,101,97,52,54,54,51,51,49,55,9 9,53,98,55,53,53,54,54,57,48,57,56,102,53,51,55,56,51,48,56,51,99],[43,99,114,101,97,116,101,95,116,97,114,103,101,116]}} terminated with reason: {http_req uest_failed,"PUT","http://localhost:5984/rs_dest_4/_local/2ea4663317c5b755669098f53783083c",{error,{code,500}}} at couch_replicator_httpc:report_error/4(li ne:341) <= couch_replicator_httpc:send_req/3(line:67) <= couch_replicator_scheduler_job:update_checkpoint/2(line:824) <= couch_replicator_scheduler_job:upd ate_checkpoint/3(line:814) <= couch_replicator_scheduler_job:do_checkpoint/1(line:787) <= couch_replicator_scheduler_job:do_last_checkpoint/1(line:551) <= gen_server:try_dispatch/4(line:615) <= gen_server:handle_msg/5(line:681) last msg: {'EXIT',<0.2642.1672>,normal} state: [{rep_id,{"2ea4663317c5b755669098f53783083c","+create_target"}},{source,"http://localhost:5984/rs_src_0/"},{target,"http://localhost:5984/rs_de st_4/"},{db_name,null},{doc_id,null},{options,[{checkpoint_interval,30000},{connection_timeout,30000},{create_target,true},{http_connections,20},{retries,5 },{socket_options,[{keepalive,true},{nodelay,false}]},{use_checkpoints,true},{worker_batch_size,500},{worker_processes,4}]},{session_id,<<"f324fa5c79c24efe 92eeaab39762d529">>},{start_seq,{0,0}},{source_seq,<<"1-g1AAAACreJzLYWBgYMlgTmEQTM4vTc5ISXIwNDLXMwBCwxygFFMiQ5L9____sxIZ8ShKcgCSSfVgdQx41OWxAEmGBiAFVLqfGLU HIGpB5mYBAGNWL7M">>},{committed_seq,{0,0}},{current_through_seq,{1,<<"1-g1AAAAEBeJzLYWBgYMlgTmEQTM4vTc5ISXIwNDLXMwBCwxygFFMiQ5L9____szKYExlzgQLs5oamKSkmFtg 04DEmyQFIJtVDTWIAm2RiaWJqaGCcwsBZmpeSmpaZl5qCx4Q8FiDJ0ACkgIbsR5hiYZhsYGJkQZIpByCm_M9KZMgCAHQhRKU">>}},{highest_seq_done,{1,<<"1-g1AAAAEBeJzLYWBgYMlgTmEQTM4 vTc5ISXIwNDLXMwBCwxygFFMiQ5L9____szKYExlzgQLs5oamKSkmFtg04DEmyQFIJtVDTWIAm2RiaWJqaGCcwsBZmpeSmpaZl5qCx4Q8FiDJ0ACkgIbsR5hiYZhsYGJkQZIpByCm_M9KZMgCAHQhRKU">> }}] [error] 2018-01-05T19:36:46.774715Z [email protected] <0.28639.1669> -------- CRASH REPORT Process (<0.28639.1669>) with 0 neighbors exited with reason: $ http_request_failed,"PUT","http://localhost:5984/rs_dest_4/_local/2ea4663317c5b755669098f53783083c",{error,{code,500}}} at gen_server:terminate/7(line:826$ <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_replicator_scheduler_job,init,['Argument__1']}, ancestors: [couch_replicator_scheduler_sup,$ ouch_replicator_sup,...], messages: [], links: [<0.349.0>], dictionary: [{task_status_props,[{changes_pending,null},{checkpoint_interval,30000},...]},...]$ trap_exit: true, status: running, heap_size: 6772, stack_size: 27, reductions: 18107 [error] 2018-01-05T19:36:46.774881Z [email protected] <0.349.0> -------- Supervisor couch_replicator_scheduler_sup had child undefined started with {couch$ replicator_scheduler_job,start_link,undefined} at <0.28639.1669> exit with reason {http_request_failed,"PUT","http://localhost:5984/rs_dest_4/_local/2ea46$ 3317c5b755669098f53783083c",{error,{code,500}}} in context child_terminated ``` ### CouchDB 1.6.1 If multiple threads are triggering replications at the same time, the server will occasionally stall for long periods of time and occasionally return with timeout errors. "Long periods of time" numerically means longer than if each thread were to run synchronously, one after the other. Verbose logging show the following message when the error occurs, then locks up: ``` [Fri, 05 Jan 2018 19:28:36 GMT] [error] [<0.4483.0>] {error_report,<0.32.0>, {<0.4483.0>,crash_report, [[{initial_call, {mochiweb_acceptor,init, ['Argument__1','Argument__2','Argument__3']}}, {pid,<0.4483.0>}, {registered_name,[]}, {error_info, {exit, {timeout, {gen_server,call,[couch_httpd_vhost,get_state]}}, [{gen_server,call,2, [{file,"gen_server.erl"},{line,204}]}, {couch_httpd_vhost,dispatch_host,1, [{file,"couch_httpd_vhost.erl"},{line,96}]}, {couch_httpd,handle_request,5, [{file,"couch_httpd.erl"},{line,217}]}, {mochiweb_http,headers,5, [{file,"mochiweb_http.erl"},{line,94}]}, {proc_lib,init_p_do_apply,3, [{file,"proc_lib.erl"},{line,240}]}]}}, {ancestors, [couch_httpd,couch_secondary_services, couch_server_sup,<0.33.0>]}, {messages, [{#Ref<0.0.262145.92883>, {vhosts_state,[], ["_utils","_uuids","_session","_oauth","_users"], #Fun<couch_httpd.8.11472519>}}]}, {links,[<0.99.0>,#Port<0.6333>]}, {dictionary,[{couch_rewrite_count,0}]}, {trap_exit,false}, {status,running}, {heap_size,2586}, {stack_size,27}, {reductions,14911}], []]}} ``` Eventually, there is a request timeout error. This can cause execution time to reach over 1.5x the synchronous upper limit, and sometimes substantially longer. Occasionally, this can also cause CouchDB 1.6.1 to completely freeze with no log output or other indications of activity. When a crash occurs, the log output is: ``` [Fri, 05 Jan 2018 20:08:59 GMT] [error] [<0.6673.0>] ** Generic server couch_server terminating ** Last message in was {#Ref<0.0.1048579.8596>, {ok,{db,<0.6686.0>,<0.6687.0>,nil, <<"1515181979786019">>,<0.6688.0>,<0.6684.0>, <0.6689.0>, {db_header,6,1,0, {2125,{1,0,1963},95}, {2042,1,83}, nil,0,nil,nil,1000}, 1, {btree,<0.6684.0>, {2125,{1,0,1963},95}, #Fun<couch_db_updater.10.21234455>, #Fun<couch_db_updater.11.21234455>, #Fun<couch_btree.5.131744168>, #Fun<couch_db_updater.12.21234455>,snappy}, {btree,<0.6684.0>, {2042,1,83}, #Fun<couch_db_updater.13.21234455>, #Fun<couch_db_updater.14.21234455>, #Fun<couch_btree.5.131744168>, #Fun<couch_db_updater.15.21234455>,snappy}, {btree,<0.6684.0>,nil, #Fun<couch_btree.3.131744168>, #Fun<couch_btree.4.131744168>, #Fun<couch_btree.5.131744168>,nil,snappy}, 1,<<"_users">>, "/var/lib/couchdb/_users.couch", [#Fun<couch_doc.8.104915127>], [],nil, {user_ctx,null,[],undefined}, nil,1000, [before_header,after_header,on_file_open], [{before_doc_update, #Fun<couch_users_db.before_doc_update.2>}, {after_doc_read, #Fun<couch_users_db.after_doc_read.2>}, sys_db, {user_ctx, {user_ctx,null,[<<"_admin">>],undefined}}, nologifmissing,sys_db], snappy, #Fun<couch_users_db.before_doc_update.2>, #Fun<couch_users_db.after_doc_read.2>}}} ** When Server state == {server,"/var/lib/couchdb", {re_pattern,0,0,0, <<69,82,67,80,140,0,0,0,16,0,0,0,1,0,0,0,255, 255,255,255,255,255,255,255,0,0,0,0,0,0,0,0, 0,0,64,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0, 0,0,0,0,0,0,0,0,0,0,0,125,0,72,25,106,0,0,0, 0,0,0,0,0,0,0,0,0,254,255,255,7,0,0,0,0,0,0, 0,0,0,0,0,0,0,0,0,0,106,0,0,0,0,16,171,255, 3,0,0,0,128,254,255,255,7,0,0,0,0,0,0,0,0,0, 0,0,0,0,0,0,0,98,27,114,0,72,0>>}, 300,0,"Fri, 05 Jan 2018 19:52:51 GMT"} ** Reason for termination == ** {kill,[{couch_server,handle_info,2,[{file,"couch_server.erl"},{line,479}]}, {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,615}]}, {gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,681}]}, {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]} [Fri, 05 Jan 2018 20:09:06 GMT] [error] [<0.6673.0>] {error_report,<0.32.0>, {<0.6673.0>,crash_report, [[{initial_call,{couch_server,init,['Argument__1']}}, {pid,<0.6673.0>}, {registered_name,couch_server}, {error_info, {exit,kill, [{gen_server,terminate,7, [{file,"gen_server.erl"},{line,826}]}, {proc_lib,init_p_do_apply,3, [{file,"proc_lib.erl"},{line,240}]}]}}, {ancestors, [couch_primary_services,couch_server_sup,<0.33.0>]}, {messages, [{'$gen_call', {<0.6674.0>,#Ref<0.0.1048579.8601>}, {create,<<"_users">>, [{before_doc_update, #Fun<couch_users_db.before_doc_update.2>}, {after_doc_read, #Fun<couch_users_db.after_doc_read.2>}, sys_db, {user_ctx, {user_ctx,null,[<<"_admin">>],undefined}}, nologifmissing,sys_db]}}, {'$gen_call', {<0.6493.0>,#Ref<0.0.1048581.39353>}, {open,<<"rs_src_0">>, [{user_ctx, {user_ctx,null, [<<"_admin">>], <<"{couch_httpd_auth, default_authentication_handler}">>}}]}}, *********** SNIPPED (repeating) *********** {links,[<0.83.0>]}, {dictionary,[]}, {trap_exit,true}, {status,running}, {heap_size,2586}, {stack_size,27}, {reductions,5686}], []]}} ``` ## Possible Solution Based on the fact that the issue only sometimes occurs and is more likely to show up when there are more threads, I am inclined to think this is a race condition. It also seems to happen more frequently if the replications are using the same source database, which might indicate that the race condition is involved with reading the source database. That is only a hunch, however. ## Steps to Reproduce (for bugs) A script to replicate the issue is here: https://gist.github.com/ReeceStevens/35d2cb06f820d3f054c6ff8dc226ef17 1. Make sure a couchDB server is running on `localhost:5984` 2. `python test_parallel_replication.py --threads 10 --iterations 40 --single-source` (we have had the most luck replicating the issue with these parameters) 3. Look for a 500 error, or for the elapsed execution time to exceed the synchronous upper limit (you will see a "LONGER THAN SYNCHRONOUS" log message when this is the case). ## Context <!--- How has this issue affected you? What are you trying to accomplish? --> <!--- Providing context helps us come up with a solution that is most useful in the real world --> We are using CouchDB 1.6.1; during product testing, we will often perform replications of large documents simultaneously. We are seeing about 3 or 4 test failures every run that are related to a hanging replication process-- they are not the same tests failing, and when run in isolation they pass. We did not see the same behavior in CouchDB 2.1.1 but are blocked from moving to that version due to https://github.com/apache/couchdb/issues/745. I believe we did not see this issue in 2.1.1 because it fails much more quickly and we retry requests on failure. ## Your Environment <!--- Include as many relevant details about the environment you experienced the bug in --> * Version used: 1.6.1 * Operating System and version (desktop or mobile): Ubuntu 16.04 server
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
