Test failure in compact.js

[davisp]

Seems like a new one and a bit of an oddity.

Travis log:

==> couchdb (eunit)
make[1]: Leaving directory `/home/travis/build/apache/couchdb'
make[1]: Entering directory `/home/travis/build/apache/couchdb'
test/javascript/tests/all_docs.js                              pass
test/javascript/tests/attachment_names.js                      pass
test/javascript/tests/attachment_paths.js                      pass
test/javascript/tests/attachment_ranges.js                     pass
test/javascript/tests/attachment_views.js                      pass
test/javascript/tests/attachments.js                           pass
test/javascript/tests/attachments_multipart.js                 pass
test/javascript/tests/auth_cache.js                            pass
test/javascript/tests/basics.js                                pass
test/javascript/tests/batch_save.js                            pass
test/javascript/tests/bulk_docs.js                             pass
test/javascript/tests/changes.js                               pass
test/javascript/tests/coffee.js                                pass
test/javascript/tests/compact.js                               
    Error: Failed to execute HTTP request: couldn't connect to host
Trace back (most recent call first):
    
  37: test/javascript/couch_http.js
      ("")
 468: 127.0.0.1/_system")@test/javascript/couch.js
      ("GET","/_node/node1
  75: test/javascript/test_setup.js
      getUptime()
  95: test/javascript/test_setup.js
      restartServer()
  57: test/javascript/tests/compact.js
      ()
  37: test/javascript/cli_runner.js
      runTest()
  48: test/javascript/cli_runner.js
      
�[31mfail
=======================================================
JavaScript tests complete.
  Failed: 1.  Skipped or passed: 13.
make[1]: *** [javascript] Error 1
make[1]: Leaving directory `/home/travis/build/apache/couchdb'
make: *** [check] Error 2

And the dev/logs/node1.log from the uploaded report

[info] 2017-07-12T22:04:08.243221Z node1@127.0.0.1 <0.7.0> -------- Application couch_log started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.244195Z node1@127.0.0.1 <0.7.0> -------- Application folsom started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.273907Z node1@127.0.0.1 <0.7.0> -------- Application couch_stats started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.274377Z node1@127.0.0.1 <0.7.0> -------- Application crypto started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.276054Z node1@127.0.0.1 <0.7.0> -------- Application sasl started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.277534Z node1@127.0.0.1 <0.7.0> -------- Application inets started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.277786Z node1@127.0.0.1 <0.7.0> -------- Application asn1 started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.278060Z node1@127.0.0.1 <0.7.0> -------- Application public_key started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.278683Z node1@127.0.0.1 <0.7.0> -------- Application ssl started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.305258Z node1@127.0.0.1 <0.7.0> -------- Application os_mon started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.321391Z node1@127.0.0.1 <0.7.0> -------- Application ibrowse started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.321690Z node1@127.0.0.1 <0.7.0> -------- Application xmerl started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.321930Z node1@127.0.0.1 <0.7.0> -------- Application compiler started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.322159Z node1@127.0.0.1 <0.7.0> -------- Application syntax_tools started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.322391Z node1@127.0.0.1 <0.7.0> -------- Application mochiweb started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.322632Z node1@127.0.0.1 <0.7.0> -------- Application b64url started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.322854Z node1@127.0.0.1 <0.7.0> -------- Application khash started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.323672Z node1@127.0.0.1 <0.7.0> -------- Application couch_event started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.324164Z node1@127.0.0.1 <0.7.0> -------- Application ioq started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:08.324407Z node1@127.0.0.1 <0.216.0> -------- Apache CouchDB 2.1.0-e05ae1c is starting.

[info] 2017-07-12T22:04:08.324594Z node1@127.0.0.1 <0.217.0> -------- Starting couch_sup
[info] 2017-07-12T22:04:10.441495Z node1@127.0.0.1 <0.216.0> -------- Apache CouchDB has started. Time to relax.

[info] 2017-07-12T22:04:10.441582Z node1@127.0.0.1 <0.216.0> -------- Apache CouchDB has started on http://127.0.0.1:15986/
[info] 2017-07-12T22:04:10.441734Z node1@127.0.0.1 <0.7.0> -------- Application couch started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.441863Z node1@127.0.0.1 <0.7.0> -------- Application ets_lru started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.443154Z node1@127.0.0.1 <0.7.0> -------- Application rexi started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.452089Z node1@127.0.0.1 <0.327.0> -------- Opening index for db: _users idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-12T22:04:10.455477Z node1@127.0.0.1 <0.320.0> -------- Starting compaction for db "_dbs"
[info] 2017-07-12T22:04:10.460567Z node1@127.0.0.1 <0.7.0> -------- Application mem3 started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.460618Z node1@127.0.0.1 <0.7.0> -------- Application fabric started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.467160Z node1@127.0.0.1 <0.7.0> -------- Application chttpd started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.468730Z node1@127.0.0.1 <0.7.0> -------- Application setup started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.468864Z node1@127.0.0.1 <0.7.0> -------- Application couch_peruser started on node 'node1@127.0.0.1'
[notice] 2017-07-12T22:04:10.470615Z node1@127.0.0.1 <0.74.0> -------- config: [features] scheduler set to true for reason nil
[info] 2017-07-12T22:04:10.479206Z node1@127.0.0.1 <0.7.0> -------- Application couch_replicator started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.479397Z node1@127.0.0.1 <0.7.0> -------- Application bear started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.482266Z node1@127.0.0.1 <0.7.0> -------- Application global_changes started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.482538Z node1@127.0.0.1 <0.7.0> -------- Application couch_plugins started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.485953Z node1@127.0.0.1 <0.7.0> -------- Application runtime_tools started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.486659Z node1@127.0.0.1 <0.7.0> -------- Application ddoc_cache started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.487439Z node1@127.0.0.1 <0.7.0> -------- Application couch_index started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.487690Z node1@127.0.0.1 <0.7.0> -------- Application couch_mrview started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.487927Z node1@127.0.0.1 <0.7.0> -------- Application snappy started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.488168Z node1@127.0.0.1 <0.7.0> -------- Application jiffy started on node 'node1@127.0.0.1'
[info] 2017-07-12T22:04:10.490912Z node1@127.0.0.1 <0.7.0> -------- Application mango started on node 'node1@127.0.0.1'
[notice] 2017-07-12T22:04:10.557583Z node1@127.0.0.1 <0.320.0> -------- Compaction swap for db: /home/travis/build/apache/couchdb/dev/lib/node1/data/_dbs.couch 209086 20670
[info] 2017-07-12T22:04:10.558894Z node1@127.0.0.1 <0.320.0> -------- Compaction for db "_dbs" completed.
[info] 2017-07-12T22:04:10.573322Z node1@127.0.0.1 <0.474.0> -------- Opening index for db: _replicator idx: _design/_replicator sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-12T22:04:10.623009Z node1@127.0.0.1 <0.484.0> -------- Starting compaction for db "shards/60000000-7fffffff/_global_changes.1499896983"
[notice] 2017-07-12T22:04:10.697090Z node1@127.0.0.1 <0.484.0> -------- Compaction swap for db: /home/travis/build/apache/couchdb/dev/lib/node1/data/shards/60000000-7fffffff/_global_changes.1499896983.couch 135358 12478
[info] 2017-07-12T22:04:10.705956Z node1@127.0.0.1 <0.484.0> -------- Compaction for db "shards/60000000-7fffffff/_global_changes.1499896983" completed.
[info] 2017-07-12T22:04:10.830374Z node1@127.0.0.1 <0.561.0> -------- Opening index for db: shards/40000000-5fffffff/_users.1499896983 idx: _design/_auth sig: "3e823c2a4383ac0c18d4e574135a5b08"
[info] 2017-07-12T22:04:10.853621Z node1@127.0.0.1 <0.580.0> -------- Opening index for db: shards/80000000-9fffffff/_replicator.1499896983 idx: _design/_replicator sig: "3e823c2a4383ac0c18d4e574135a5b08"
[notice] 2017-07-12T22:04:11.018617Z node1@127.0.0.1 <0.343.0> ac9d241d53 127.0.0.1:15984 127.0.0.1 undefined GET / 200 ok 1
[os_mon] memory supervisor port (memsup): Erlang has closed
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed
[os_mon] memory supervisor port (memsup): Erlang has closed

I don't understand how the previous tests aren't showing up in that log.

[wohali]

See #673 - related?

[davisp]

Could be. I can't figure out how we're not getting logs from the tests that are reported as passing in the same run.

@wohali What do you think about adding a few commands to the script just before starting the javascript test suite to check on host health? I'm thinking of checking things like df, free, netstat, and maybe something like ps ax | wc -l or similar to try and get an idea of what we might be hitting. Also might be useful to add collecting whatever logs OOM-killer actions into our couchlog uploads incase we're seeing memory issues that you mentioned the other day.

[nickva]

I did some of that in the jenkins-pipeline branch:

couchdb/Makefile

Lines 92 to 103 in 32eb49a

	@echo "********* environment info ******** "
	@cat /proc/meminfo
	@free -m
	@sh -c 'ulimit -a'
	@grep -r '.*' /sys/fs/cgroup/memory/ || true
	@tail -n 20 /proc/cpuinfo || true
	@echo "******** environment info end ***** "
	@echo "******** core file pattern:"
	@ls -l /proc/sys/kernel/core_pattern || true
	@cat /proc/sys/kernel/core_pattern || true
	@cat /usr/share/apport/apport || true
	@echo "************"

It's a good idea. Even crazier could have a mini benchmark - try to write to disk, read back, run a few cpu speed tests, memory usage etc. And maybe decide test environment is just crappy and give up. Cause it certainly seems crappy a lot of the times.

[wohali]

@davisp we lose it because dev/run nukes the logfile when restarting the node. I considered changing this code about a week ago, but it would never clean up the logfile in that case, making a local dev instance's logfile grow until someone manually cleaned it out.

In short dev/run should be enhanced so node restart doesn't wipe a logfile, but node initial-startup does.