compaction eunit test failure: database not idle after compaction complete

[wohali]

Normally, the couchdb_compaction_daemon_tests test should_compact_by_default_rule test passes. Sometimes, though, it fails.

Example:

https://builds.apache.org/blue/organizations/jenkins/CouchDB/detail/master/11/pipeline/46

Node environment: ubuntu1404erlang183

makefile output:

module 'couch_query_servers'
  couch_query_servers: builtin_sum_rows_negative_test...ok
  couch_query_servers: sum_values_test...ok
  couch_query_servers: sum_values_negative_test...ok
  couch_query_servers: stat_values_test...ok
  [done in 0.012 s]
module 'couchdb_compaction_daemon_tests'
  Compaction daemon tests
    couchdb_compaction_daemon_tests:74: should_compact_by_default_rule...*failed*
in function couchdb_compaction_daemon_tests:'-should_compact_by_default_rule/1-fun-6-'/1 (test/couchdb_compaction_daemon_tests.erl, line 104)
in call from couchdb_compaction_daemon_tests:'-should_compact_by_default_rule/1-fun-7-'/1 (test/couchdb_compaction_daemon_tests.erl, line 104)
**error:{assert,[{module,couchdb_compaction_daemon_tests},
         {line,104},
         {expression,"is_idle ( DbName )"},
         {expected,true},
         {value,false}]}
  output:<<"">>

couch.log output:

[info] 2017-06-02T21:52:10.853758Z nonode@nohost <0.17500.0> -------- Starting index update for db: eunit-test-db-1496440307863680 idx: _design/foo
[info] 2017-06-02T21:52:10.857486Z nonode@nohost <0.17500.0> -------- Index update finished for db: eunit-test-db-1496440307863680 idx: _design/foo
[notice] 2017-06-02T21:52:10.858153Z nonode@nohost <0.17441.0> -------- 127.0.0.1 - - GET /eunit-test-db-1496440307863680/_design/foo/_view/foo 200
[info] 2017-06-02T21:52:10.917842Z nonode@nohost <0.17500.0> -------- Starting index update for db: eunit-test-db-1496440307863680 idx: _design/foo
[info] 2017-06-02T21:52:10.921713Z nonode@nohost <0.17500.0> -------- Index update finished for db: eunit-test-db-1496440307863680 idx: _design/foo
[notice] 2017-06-02T21:52:10.922582Z nonode@nohost <0.17441.0> -------- 127.0.0.1 - - GET /eunit-test-db-1496440307863680/_design/foo/_view/foo 200
[notice] 2017-06-02T21:52:10.974547Z nonode@nohost <0.17273.0> -------- config: [compactions] _default set to [{db_fragmentation, "70%"}, {view_fragmentation, "70%"}] for reason nil
[info] 2017-06-02T21:52:10.993547Z nonode@nohost <0.19743.0> -------- Opening index for db: eunit-test-db-1496440225289901 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.002863Z nonode@nohost <0.19752.0> -------- Opening index for db: eunit-test-db-1496440225785011 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.007746Z nonode@nohost <0.19761.0> -------- Opening index for db: eunit-test-db-1496440225463102 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.010744Z nonode@nohost <0.19770.0> -------- Opening index for db: eunit-test-db-1496440226930536 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.013218Z nonode@nohost <0.19776.0> -------- Opening index for db: _users idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.022520Z nonode@nohost <0.19788.0> -------- Opening index for db: eunit-test-db-1496440225349889 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.036829Z nonode@nohost <0.19800.0> -------- Opening index for db: eunit-test-db-1496440225526972 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.039789Z nonode@nohost <0.19809.0> -------- Opening index for db: eunit-test-db-1496440225839920 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.042615Z nonode@nohost <0.19818.0> -------- Opening index for db: eunit-test-db-1496440225648009 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.055939Z nonode@nohost <0.19833.0> -------- Opening index for db: eunit-test-db-1496440225588013 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.058763Z nonode@nohost <0.19842.0> -------- Opening index for db: eunit-test-db-1496440225753479 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.132359Z nonode@nohost <0.19884.0> -------- Opening index for db: eunit-test-db-1496440225812335 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-06-02T21:52:11.134426Z nonode@nohost <0.17489.0> -------- Starting compaction for db "eunit-test-db-1496440307863680"
[notice] 2017-06-02T21:52:11.358111Z nonode@nohost <0.17489.0> -------- Compaction swap for db: /tmp/tmp.h5tfKaIecF/apache-couchdb-2.1.0-4a0cd89/tmp/data/eunit-test-db-1496440307863680.couch 1646789 53445
[info] 2017-06-02T21:52:11.361754Z nonode@nohost <0.17489.0> -------- Compaction for db "eunit-test-db-1496440307863680" completed.
[info] 2017-06-02T21:52:11.364188Z nonode@nohost <0.19897.0> -------- Compaction started for db: eunit-test-db-1496440307863680 idx: _design/foo
[notice] 2017-06-02T21:52:11.381542Z nonode@nohost <0.17497.0> -------- Compaction swap for view /tmp/tmp.h5tfKaIecF/apache-couchdb-2.1.0-4a0cd89/tmp/data/.eunit-test-db-1496440307863680_design/mrview/ee2c720a13443ab1d50210242730ca31.view 440970 28800
[notice] 2017-06-02T21:52:11.384063Z nonode@nohost <0.17273.0> -------- config: [compactions] _default deleted for reason nil
[info] 2017-06-02T21:52:11.385263Z nonode@nohost <0.19897.0> -------- Compaction finished for db: eunit-test-db-1496440307863680 idx: _design/foo
[info] 2017-06-02T21:52:11.388504Z nonode@nohost <0.17497.0> -------- Index shutdown by monitor notice for db: eunit-test-db-1496440307863680 idx: _design/foo
[info] 2017-06-02T21:52:11.389493Z nonode@nohost <0.17497.0> -------- Closing index for db: eunit-test-db-1496440307863680 idx: _design/foo sig: "ee2c720a13443ab1d50210242730ca31" because normal
[error] 2017-06-02T21:52:11.406481Z nonode@nohost <0.17457.0> -------- gen_server couch_compaction_daemon terminated with reason: {not_mocked,couch_compaction_daemon} at meck_proc:gen_server/3(line:450) <= meck_code_gen:exec/4(line:147) <= gen_server:try_dispatch/4(line:615) <= gen_server:handle_msg/5(line:681) <= proc_lib:init_p_do_apply/3(line:240)
  last msg: {'EXIT',<0.17459.0>,killed}
     state: {state,<0.17459.0>,[]}
[error] 2017-06-02T21:52:11.407573Z nonode@nohost <0.17457.0> -------- CRASH REPORT Process couch_compaction_daemon (<0.17457.0>) with 0 neighbors exited with reason: {not_mocked,couch_compaction_daemon} at meck_proc:gen_server/3(line:450) <= meck_code_gen:exec/4(line:147) <= gen_server:try_dispatch/4(line:615) <= gen_server:handle_msg/5(line:681) <= proc_lib:init_p_do_apply/3(line:240) at gen_server:terminate/7(line:826) <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_compaction_daemon,init,['Argument__1']}, ancestors: [couch_secondary_services,couch_sup,<0.17421.0>], messages: [], links: [<0.17430.0>], dictionary: [], trap_exit: true, status: running, heap_size: 1598, stack_size: 27, reductions: 1264
[error] 2017-06-02T21:52:11.407930Z nonode@nohost <0.17430.0> -------- Supervisor couch_secondary_services had child compaction_daemon started with couch_compaction_daemon:start_link() at <0.17457.0> exit with reason {not_mocked,couch_compaction_daemon} at meck_proc:gen_server/3(line:450) <= meck_code_gen:exec/4(line:147) <= gen_server:try_dispatch/4(line:615) <= gen_server:handle_msg/5(line:681) <= proc_lib:init_p_do_apply/3(line:240) in context child_terminated

Possible Solution

I see that wait_for_compaction only waits on the pid for the compaction of the DB itself. In fact, the config:delete call happens immediately after the compaction for the DB complete, but the compaction for the DB's view _design/foo is still ongoing.

I wonder if the subsequent compaction of the view as well is setting up a monitor on the DB which is failing the is_idle check.

[eiri]

So, this took some chasing to figure out. The function wait_for_compaction is actually waiting on compaction monitor, not db compaction and since we have parallel_view_compact set to false in compaction daemon, the whole thing is sequential and doesn't have a race.

There are, however, a race in view compacting process (not compactor server, but actual compacting worker). The issue is that we reuse same data dir for all the tests, so there are quite a few temp database leftovers from the previous tests. Since compaction daemon scans all the databases on compact by default rule test, this creates quite a crowd, so on starved resources compacting process could be slightly slow to release db monitor even after swap_compacted called.

I've opened #614 to ensure "our" compacting proc exits before we do the db idling test.