eunit couchdb_os_daemons_tests race on startup

[wohali]

Expected & Current Behaviour

The couchdb_os_daemons_tests test should always pass, but sometimes, it fails a context cleanup.

• https://builds.apache.org/blue/organizations/jenkins/CouchDB/detail/2.1.x/3/pipeline
• Jenkins, Debian 8, default Erlang (17)

Makefile output:

module 'couchdb_os_daemons_tests'
  OS Daemons tests
    couchdb_os_daemons_tests:107: should_check_daemon...ok
    couchdb_os_daemons_tests:113: should_check_daemon_table_form...ok
    couchdb_os_daemons_tests:120: should_clean_tables_on_daemon_remove...[0.544 s] ok
    couchdb_os_daemons_tests:127: should_spawn_multiple_daemons...[0.618 s] ok
    undefined
    *** context cleanup failed ***
**in function test_util:stop_sync_throw/4 (src/test_util.erl, line 160)
in call from couchdb_os_daemons_tests:teardown/2 (test/couchdb_os_daemons_tests.erl, line 58)
**throw:{timeout,os_daemon_stop}

couch.log content:

[notice] 2017-06-06T22:50:22.237455Z nonode@nohost <0.3536.1> -------- config: [os_daemons] os_daemon_looper.escript deleted for reason nil
[info] 2017-06-06T22:50:22.795306Z nonode@nohost <0.7.0> -------- Application couch_epi exited with reason: stopped
[info] 2017-06-06T22:50:22.796319Z nonode@nohost <0.7.0> -------- Application ioq exited with reason: stopped
[info] 2017-06-06T22:50:22.825941Z nonode@nohost <0.7.0> -------- Application couch_log started on node nonode@nohost
[info] 2017-06-06T22:50:22.826318Z nonode@nohost <0.7.0> -------- Application ioq started on node nonode@nohost
[info] 2017-06-06T22:50:22.907640Z nonode@nohost <0.7.0> -------- Application couch_epi started on node nonode@nohost
[notice] 2017-06-06T22:50:23.068667Z nonode@nohost <0.3593.1> -------- config: [os_daemons] os_daemon_looper.escript set to /tmp/tmp.rGuUi1aWRx/apache-couchdb-2.0.0-76d2aee/src/couch/test/fixtures/os_daemon_looper.escript for reason nil
[notice] 2017-06-06T22:50:23.071633Z nonode@nohost <0.3593.1> -------- config: [uuids] algorithm set to sequential for reason nil
[notice] 2017-06-06T22:50:23.677403Z nonode@nohost <0.3593.1> -------- config: [os_daemons] bar set to /tmp/tmp.rGuUi1aWRx/apache-couchdb-2.0.0-76d2aee/src/couch/test/fixtures/os_daemon_looper.escript for reason nil
[notice] 2017-06-06T22:50:23.677893Z nonode@nohost <0.3593.1> -------- config: [os_daemons] baz set to /tmp/tmp.rGuUi1aWRx/apache-couchdb-2.0.0-76d2aee/src/couch/test/fixtures/os_daemon_looper.escript for reason nil
[info] 2017-06-06T22:50:25.320943Z nonode@nohost <0.7.0> -------- Application inets started on node nonode@nohost
[info] 2017-06-06T22:50:25.323433Z nonode@nohost <0.7.0> -------- Application ibrowse started on node nonode@nohost
[info] 2017-06-06T22:50:25.323627Z nonode@nohost <0.7.0> -------- Application asn1 started on node nonode@nohost
[info] 2017-06-06T22:50:25.323845Z nonode@nohost <0.7.0> -------- Application public_key started on node nonode@nohost
[info] 2017-06-06T22:50:25.324464Z nonode@nohost <0.7.0> -------- Application ssl started on node nonode@nohost
[info] 2017-06-06T22:50:25.324723Z nonode@nohost <0.7.0> -------- Application khash started on node nonode@nohost
[info] 2017-06-06T22:50:25.325443Z nonode@nohost <0.7.0> -------- Application couch_event started on node nonode@nohost
[info] 2017-06-06T22:50:25.326306Z nonode@nohost <0.7.0> -------- Application sasl started on node nonode@nohost
[info] 2017-06-06T22:50:25.328126Z nonode@nohost <0.7.0> -------- Application os_mon started on node nonode@nohost
[info] 2017-06-06T22:50:25.328339Z nonode@nohost <0.7.0> -------- Application xmerl started on node nonode@nohost
[info] 2017-06-06T22:50:25.328526Z nonode@nohost <0.7.0> -------- Application compiler started on node nonode@nohost
[info] 2017-06-06T22:50:25.328700Z nonode@nohost <0.7.0> -------- Application syntax_tools started on node nonode@nohost
[info] 2017-06-06T22:50:25.328873Z nonode@nohost <0.7.0> -------- Application mochiweb started on node nonode@nohost
[info] 2017-06-06T22:50:25.329045Z nonode@nohost <0.7.0> -------- Application oauth started on node nonode@nohost
[info] 2017-06-06T22:50:25.329212Z nonode@nohost <0.7.0> -------- Application b64url started on node nonode@nohost
[info] 2017-06-06T22:50:25.329750Z nonode@nohost <0.7.0> -------- Application folsom started on node nonode@nohost
[info] 2017-06-06T22:50:25.366232Z nonode@nohost <0.7.0> -------- Application couch_stats started on node nonode@nohost
[info] 2017-06-06T22:50:25.366227Z nonode@nohost <0.3762.1> -------- Apache CouchDB 2.0.0 is starting.

[info] 2017-06-06T22:50:25.366569Z nonode@nohost <0.3763.1> -------- Starting couch_sup
[error] 2017-06-06T22:50:25.383949Z nonode@nohost <0.3771.1> -------- Supervisor couch_secondary_services had child os_daemons started with couch_os_daemons:start_link() at undefined exit with reason {already_started,<0.3640.1>} in context start_error
[error] 2017-06-06T22:50:25.384692Z nonode@nohost <0.3763.1> -------- Supervisor couch_sup had child couch_secondary_services started with couch_secondary_sup:start_link() at undefined exit with reason {shutdown,{failed_to_start_child,os_daemons,{already_started,<0.3640.1>}}} in context start_error
[error] 2017-06-06T22:50:25.385050Z nonode@nohost <0.3762.1> -------- Error starting Apache CouchDB:

    {error,{shutdown,{failed_to_start_child,couch_secondary_services,{shutdown,{failed_to_start_child,os_daemons,{already_started,<0.3640.1>}}}}}}


[error] 2017-06-06T22:50:25.386914Z nonode@nohost <0.3761.1> -------- CRASH REPORT Process  (<0.3761.1>) with 0 neighbors exited with reason: {{shutdown,{failed_to_start_child,couch_secondary_services,{shutdown,{failed_to_start_child,os_daemons,{already_started,<0.3640.1>}}}}},{couch_app,start,[normal,[]]}} at application_master:init/4(line:133) <= proc_lib:init_p_do_apply/3(line:237); initial_call: {application_master,init,['Argument__1','Argument__2',...]}, ancestors: [<0.3760.1>], messages: [{'EXIT',<0.3762.1>,normal}], links: [<0.3760.1>,<0.7.0>], dictionary: [], trap_exit: true, status: running, heap_size: 610, stack_size: 27, reductions: 132
[info] 2017-06-06T22:50:25.387276Z nonode@nohost <0.7.0> -------- Application couch exited with reason: {{shutdown,{failed_to_start_child,couch_secondary_services,{shutdown,{failed_to_start_child,os_daemons,{already_started,<0.3640.1>}}}}},{couch_app,start,[normal,[]]}}

Analysis

Possibly bump timeout more?

The test spawns the file src/couch/test/fixtures/os_daemon_looper.escript. Perhaps this daemon is out to lunch on an io:read and can't be killed? I don't know.

[janl]

Could {failed_to_start_child,os_daemons,{already_started,<0.3640.1>}}} “already started” be a smoking gun?

[wohali]

That's coming from the subsequent tests, after it failed to stop it.

[wohali]

Closing as a duplicate of #571.