Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Failure waiting for db shutdown in couchdb_1283 test #655

Closed
wohali opened this issue Jul 8, 2017 · 2 comments
Closed

Failure waiting for db shutdown in couchdb_1283 test #655

wohali opened this issue Jul 8, 2017 · 2 comments
Labels
testsuite
Milestone
2.1.0

Comments

@wohali
Copy link
Member

wohali commented Jul 8, 2017

Failure scenario

    couchdb_views_tests:266: couchdb_1309...[0.188 s] ok
[os_mon] memory supervisor port (memsup): Erlang has closed
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed
    [done in 1.286 s]
  View group shutdown
    couchdb_views_tests:315: couchdb_1283...*failed*
in function couchdb_views_tests:wait_for_process_shutdown/3 (test/couchdb_views_tests.erl, line 413)
in call from couchdb_views_tests:'-couchdb_1283/0-fun-21-'/0 (test/couchdb_views_tests.erl, line 358)
**error:{assertion_failed,[{module,couchdb_views_tests},
                   {line,415},
                   {reason,"Failure waiting for db shutdown"}]}
  output:<<"">>

couch.log from a normal run:

[notice] 2017-07-07T22:56:49.895207Z nonode@nohost <0.28311.0> -------- config: [couchdb] max_dbs_open set to 3 for reason nil
[notice] 2017-07-07T22:56:49.895759Z nonode@nohost <0.28311.0> -------- config: [couchdb] delayed_commits set to false for reason nil
[info] 2017-07-07T22:56:50.079629Z nonode@nohost <0.28540.0> -------- Opening index for db: eunit-test-db-1499468209895967 idx: _design/foo sig: "0963a19eb3ef007218f1e11f0aefa2d9"
[info] 2017-07-07T22:56:50.079947Z nonode@nohost <0.28543.0> -------- Starting index update for db: eunit-test-db-1499468209895967 idx: _design/foo
[notice] 2017-07-07T22:56:50.140386Z nonode@nohost <0.28480.0> -------- 127.0.0.1 - - GET /eunit-test-db-1499468209895967/_design/foo/_view/foo 200
[info] 2017-07-07T22:56:50.142498Z nonode@nohost <0.28543.0> -------- Index update finished for db: eunit-test-db-1499468209895967 idx: _design/foo
[info] 2017-07-07T22:56:50.183784Z nonode@nohost <0.28523.0> -------- Index shutdown by monitor notice for db: eunit-test-db-1499468025801812 idx: _design/_auth
[info] 2017-07-07T22:56:50.184687Z nonode@nohost <0.28523.0> -------- Closing index for db: eunit-test-db-1499468025801812 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T22:56:50.218193Z nonode@nohost <0.28540.0> -------- Index shutdown by monitor notice for db: eunit-test-db-1499468209895967 idx: _design/foo
[info] 2017-07-07T22:56:50.218838Z nonode@nohost <0.28540.0> -------- Closing index for db: eunit-test-db-1499468209895967 idx: _design/foo sig: "0963a19eb3ef007218f1e11f0aefa2d9" because normal
[info] 2017-07-07T22:56:50.252870Z nonode@nohost <0.28565.0> -------- Opening index for db: eunit-test-db-1499468209895967 idx: _design/foo sig: "0963a19eb3ef007218f1e11f0aefa2d9"
[info] 2017-07-07T22:56:50.253604Z nonode@nohost <0.28569.0> -------- Compaction started for db: eunit-test-db-1499468209895967 idx: _design/foo
[notice] 2017-07-07T22:56:50.257055Z nonode@nohost <0.28565.0> -------- Compaction swap for view /home/joant/couchdb/tmp/data/.eunit-test-db-1499468209895967_design/mrview/0963a19eb3ef007218f1e11f0aefa2d9.view 4227 4200
[info] 2017-07-07T22:56:50.257720Z nonode@nohost <0.28569.0> -------- Compaction finished for db: eunit-test-db-1499468209895967 idx: _design/foo
[info] 2017-07-07T22:56:50.258556Z nonode@nohost <0.28565.0> -------- Index shutdown by monitor notice for db: eunit-test-db-1499468209895967 idx: _design/foo
[info] 2017-07-07T22:56:50.259171Z nonode@nohost <0.28565.0> -------- Closing index for db: eunit-test-db-1499468209895967 idx: _design/foo sig: "0963a19eb3ef007218f1e11f0aefa2d9" because normal
[info] 2017-07-07T22:56:50.282171Z nonode@nohost <0.7.0> -------- Application couch exited with reason: stopped

couch.log from THIS run. What is all this other activity?:

[notice] 2017-07-07T16:56:53.688512Z nonode@nohost <0.21667.1> -------- config: [couchdb] max_dbs_open set to 3 for reason nil
[notice] 2017-07-07T16:56:53.688851Z nonode@nohost <0.21667.1> -------- config: [couchdb] delayed_commits set to false for reason nil
[info] 2017-07-07T16:56:53.702918Z nonode@nohost <0.21896.1> -------- Opening index for db: eunit-test-db-1499446219830124 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.750851Z nonode@nohost <0.21904.1> -------- Opening index for db: eunit-test-db-1499446220623551 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.753143Z nonode@nohost <0.21876.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446516999249 idx: _design/_auth
[info] 2017-07-07T16:56:53.753985Z nonode@nohost <0.21876.1> -------- Closing index for db: eunit-test-db-1499446516999249 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.817388Z nonode@nohost <0.21896.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446219830124 idx: _design/_auth
[info] 2017-07-07T16:56:53.818029Z nonode@nohost <0.21896.1> -------- Closing index for db: eunit-test-db-1499446219830124 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.820296Z nonode@nohost <0.21904.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446220623551 idx: _design/_auth
[info] 2017-07-07T16:56:53.821161Z nonode@nohost <0.21904.1> -------- Closing index for db: eunit-test-db-1499446220623551 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.922346Z nonode@nohost <0.21944.1> -------- Opening index for db: eunit-test-db-1499446219703554 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.939247Z nonode@nohost <0.21952.1> -------- Opening index for db: eunit-test-db-1499446221813661 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.944639Z nonode@nohost <0.21960.1> -------- Opening index for db: eunit-test-db-1499446221159930 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.948209Z nonode@nohost <0.21944.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446219703554 idx: _design/_auth
[info] 2017-07-07T16:56:53.948860Z nonode@nohost <0.21944.1> -------- Closing index for db: eunit-test-db-1499446219703554 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.956116Z nonode@nohost <0.21952.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446221813661 idx: _design/_auth
[info] 2017-07-07T16:56:53.957042Z nonode@nohost <0.21974.1> -------- Opening index for db: eunit-test-db-1499446222101112 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.962492Z nonode@nohost <0.21960.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446221159930 idx: _design/_auth
[info] 2017-07-07T16:56:53.963051Z nonode@nohost <0.21952.1> -------- Closing index for db: eunit-test-db-1499446221813661 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.963858Z nonode@nohost <0.21960.1> -------- Closing index for db: eunit-test-db-1499446221159930 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.973779Z nonode@nohost <0.21988.1> -------- Opening index for db: eunit-test-db-1499446220901047 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.978437Z nonode@nohost <0.21974.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446222101112 idx: _design/_auth
[info] 2017-07-07T16:56:53.978998Z nonode@nohost <0.21974.1> -------- Closing index for db: eunit-test-db-1499446222101112 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.986384Z nonode@nohost <0.21996.1> -------- Opening index for db: eunit-test-db-1499446220401017 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:53.991042Z nonode@nohost <0.21988.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446220901047 idx: _design/_auth
[info] 2017-07-07T16:56:53.991477Z nonode@nohost <0.21988.1> -------- Closing index for db: eunit-test-db-1499446220901047 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.993689Z nonode@nohost <0.21996.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446220401017 idx: _design/_auth
[info] 2017-07-07T16:56:53.994459Z nonode@nohost <0.21996.1> -------- Closing index for db: eunit-test-db-1499446220401017 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:53.999149Z nonode@nohost <0.22016.1> -------- Opening index for db: eunit-test-db-1499446517915101 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.003248Z nonode@nohost <0.22024.1> -------- Opening index for db: eunit-test-db-1499446517274999 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.007925Z nonode@nohost <0.22032.1> -------- Opening index for db: eunit-test-db-1499446222222892 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.011046Z nonode@nohost <0.22037.1> -------- Opening index for db: _users idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.015667Z nonode@nohost <0.22016.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446517915101 idx: _design/_auth
[info] 2017-07-07T16:56:54.016440Z nonode@nohost <0.22016.1> -------- Closing index for db: eunit-test-db-1499446517915101 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:54.019066Z nonode@nohost <0.22045.1> -------- Opening index for db: eunit-test-db-1499446221704953 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.020063Z nonode@nohost <0.22024.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446517274999 idx: _design/_auth
[info] 2017-07-07T16:56:54.020789Z nonode@nohost <0.22024.1> -------- Closing index for db: eunit-test-db-1499446517274999 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:54.022707Z nonode@nohost <0.22032.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446222222892 idx: _design/_auth
[info] 2017-07-07T16:56:54.023502Z nonode@nohost <0.22032.1> -------- Closing index for db: eunit-test-db-1499446222222892 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:54.026007Z nonode@nohost <0.22056.1> -------- Opening index for db: eunit-test-db-1499446223835003 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-07T16:56:54.259704Z nonode@nohost <0.22065.1> -------- Opening index for db: eunit-test-db-1499446613689085 idx: _design/foo sig: "0963a19eb3ef007218f1e11f0aefa2d9"
[info] 2017-07-07T16:56:54.260081Z nonode@nohost <0.22068.1> -------- Starting index update for db: eunit-test-db-1499446613689085 idx: _design/foo
[info] 2017-07-07T16:56:54.348232Z nonode@nohost <0.22068.1> -------- Index update finished for db: eunit-test-db-1499446613689085 idx: _design/foo
[notice] 2017-07-07T16:56:54.348925Z nonode@nohost <0.21837.1> -------- 127.0.0.1 - - GET /eunit-test-db-1499446613689085/_design/foo/_view/foo 200
[info] 2017-07-07T16:56:54.354037Z nonode@nohost <0.22045.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446221704953 idx: _design/_auth
[info] 2017-07-07T16:56:54.354483Z nonode@nohost <0.22045.1> -------- Closing index for db: eunit-test-db-1499446221704953 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[info] 2017-07-07T16:56:54.394970Z nonode@nohost <0.22056.1> -------- Index shutdown by monitor notice for db: eunit-test-db-1499446223835003 idx: _design/_auth
[info] 2017-07-07T16:56:54.395542Z nonode@nohost <0.22056.1> -------- Closing index for db: eunit-test-db-1499446223835003 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08" because normal
[error] 2017-07-07T16:56:55.451195Z nonode@nohost <0.22040.1> -------- gen_server <0.22040.1> terminated with reason: killed
  last msg: {'EXIT',<0.22037.1>,killed}
     state: {st,<0.22037.1>,couch_mrview_index,undefined}
[error] 2017-07-07T16:56:55.451531Z nonode@nohost <0.22069.1> -------- gen_server <0.22069.1> terminated with reason: killed
  last msg: {'EXIT',<0.22065.1>,killed}
     state: {st,<0.22065.1>,couch_mrview_index,undefined}
[error] 2017-07-07T16:56:55.452005Z nonode@nohost <0.22040.1> -------- CRASH REPORT Process  (<0.22040.1>) with 0 neighbors exited with reason: killed at gen_server:terminate/7(line:826) <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_index_compactor,init,['Argument__1']}, ancestors: [<0.22037.1>,<0.22036.1>], messages: [], links: [], dictionary: [], trap_exit: true, status: running, heap_size: 376, stack_size: 27, reductions: 126
[error] 2017-07-07T16:56:55.452284Z nonode@nohost <0.22039.1> -------- gen_server <0.22039.1> terminated with reason: killed
  last msg: {'EXIT',<0.22037.1>,killed}
     state: {st,<0.22037.1>,couch_mrview_index,nil}
[error] 2017-07-07T16:56:55.452595Z nonode@nohost <0.22069.1> -------- CRASH REPORT Process  (<0.22069.1>) with 0 neighbors exited with reason: killed at gen_server:terminate/7(line:826) <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_index_compactor,init,['Argument__1']}, ancestors: [<0.22065.1>,<0.22064.1>], messages: [], links: [], dictionary: [], trap_exit: true, status: running, heap_size: 376, stack_size: 27, reductions: 123
[error] 2017-07-07T16:56:55.452807Z nonode@nohost <0.22068.1> -------- gen_server <0.22068.1> terminated with reason: killed
  last msg: {'EXIT',<0.22065.1>,killed}
     state: {st,<0.22065.1>,couch_mrview_index,undefined}
[error] 2017-07-07T16:56:55.453190Z nonode@nohost <0.22039.1> -------- CRASH REPORT Process  (<0.22039.1>) with 0 neighbors exited with reason: killed at gen_server:terminate/7(line:826) <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_index_updater,init,['Argument__1']}, ancestors: [<0.22037.1>,<0.22036.1>], messages: [], links: [], dictionary: [], trap_exit: true, status: running, heap_size: 376, stack_size: 27, reductions: 138
[error] 2017-07-07T16:56:55.453540Z nonode@nohost <0.22068.1> -------- CRASH REPORT Process  (<0.22068.1>) with 0 neighbors exited with reason: killed at gen_server:terminate/7(line:826) <= proc_lib:init_p_do_apply/3(line:240); initial_call: {couch_index_updater,init,['Argument__1']}, ancestors: [<0.22065.1>,<0.22064.1>], messages: [], links: [], dictionary: [], trap_exit: true, status: running, heap_size: 987, stack_size: 27, reductions: 1738
[info] 2017-07-07T16:56:55.453791Z nonode@nohost <0.7.0> -------- Application couch exited with reason: stopped
@wohali wohali added this to the 2.1.0 milestone Jul 8, 2017
@wohali
Copy link
Member Author

wohali commented Jul 8, 2017 •
edited

FYI, a reminder that COUCHDB-1283 is: "Impossible to compact view groups when number of active databases > max_dbs_open". Is a fix for this issue still valid for 2.0, @rnewson ?

@wohali
Copy link
Member Author

wohali commented Jul 11, 2017

A new instance of this:

davisp added a commit that referenced this issue Jul 12, 2017
@davisp
Fix timeout in couchdb_views_test for couchdb_1283
a50dd7e 
I believe the race here was that the query could return before the
actual index updating process exited. Then it was just a race to
creating a database before the monitor is released.

If we do end up creating the database before the monitor is released
then the database we want to have closed ends up being ignored as its
not idle. The second two created databases then don't end up forcing the
database from couch_server's LRU which leads us to the timeout waiting
for DatabaseMonRef to fire.

Fixes #655
@davisp davisp mentioned this issue Jul 12, 2017
Merged
@davisp davisp closed this as completed in 11afc8b Jul 13, 2017
@davisp davisp mentioned this issue Jul 13, 2017
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
testsuite
Projects
None yet
Milestone
2.1.0
Development

No branches or pull requests
1 participant
@wohali