You are viewing a plain text version of this content. The canonical link for it is here.

Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2015/08/13 20:00:13 UTC

Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #703

See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/703/changes>

Changes:

[vinodkone] Exposed environment variables LIBPROCESS_ADVERTISE_IP and

[vinodkone] Added 2 master flags --advertise_ip and --advertise_port.

------------------------------------------
[...truncated 118138 lines...]
I0813 18:00:59.829804 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 158ns
I0813 18:00:59.829835 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.830921 27125 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 612354ns
I0813 18:00:59.830955 27125 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.834482 27097 leveldb.cpp:176] Opened db in 2.897487ms
I0813 18:00:59.837293 27097 leveldb.cpp:183] Compacted db in 2.770934ms
I0813 18:00:59.837371 27097 leveldb.cpp:198] Created db iterator in 19939ns
I0813 18:00:59.837410 27097 leveldb.cpp:204] Seeked to beginning of db in 20807ns
I0813 18:00:59.837446 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 21322ns
I0813 18:00:59.837483 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.840483 27097 leveldb.cpp:176] Opened db in 2.839851ms
I0813 18:00:59.843341 27097 leveldb.cpp:183] Compacted db in 2.794442ms
I0813 18:00:59.843400 27097 leveldb.cpp:198] Created db iterator in 18987ns
I0813 18:00:59.843436 27097 leveldb.cpp:204] Seeked to beginning of db in 19902ns
I0813 18:00:59.843473 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 21512ns
I0813 18:00:59.843509 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.843986 27131 recover.cpp:449] Starting replica recovery
I0813 18:00:59.844211 27131 recover.cpp:475] Replica is in VOTING status
I0813 18:00:59.844570 27131 recover.cpp:464] Recover process terminated
I0813 18:00:59.847435 27126 registrar.cpp:311] Recovering registrar
[       OK ] Strict/RegistrarTest.FetchTimeout/0 (52 ms)
[ RUN      ] Strict/RegistrarTest.FetchTimeout/1
Using temporary directory '/tmp/Strict_RegistrarTest_FetchTimeout_1_uhIU1m'
I0813 18:00:59.876332 27097 leveldb.cpp:176] Opened db in 3.213648ms
I0813 18:00:59.877480 27097 leveldb.cpp:183] Compacted db in 1.109003ms
I0813 18:00:59.877535 27097 leveldb.cpp:198] Created db iterator in 14100ns
I0813 18:00:59.877555 27097 leveldb.cpp:204] Seeked to beginning of db in 1785ns
I0813 18:00:59.877567 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 170ns
I0813 18:00:59.877598 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.878993 27130 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 847789ns
I0813 18:00:59.879030 27130 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.882300 27097 leveldb.cpp:176] Opened db in 2.715285ms
I0813 18:00:59.883430 27097 leveldb.cpp:183] Compacted db in 1.061899ms
I0813 18:00:59.883486 27097 leveldb.cpp:198] Created db iterator in 13812ns
I0813 18:00:59.883505 27097 leveldb.cpp:204] Seeked to beginning of db in 1525ns
I0813 18:00:59.883515 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 175ns
I0813 18:00:59.883546 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.885128 27119 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 599317ns
I0813 18:00:59.885241 27119 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.888790 27097 leveldb.cpp:176] Opened db in 2.958281ms
I0813 18:00:59.891683 27097 leveldb.cpp:183] Compacted db in 2.852636ms
I0813 18:00:59.891744 27097 leveldb.cpp:198] Created db iterator in 19209ns
I0813 18:00:59.891783 27097 leveldb.cpp:204] Seeked to beginning of db in 19022ns
I0813 18:00:59.891839 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 32202ns
I0813 18:00:59.891901 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.895509 27097 leveldb.cpp:176] Opened db in 3.404201ms
I0813 18:00:59.898675 27097 leveldb.cpp:183] Compacted db in 3.127029ms
I0813 18:00:59.898736 27097 leveldb.cpp:198] Created db iterator in 18152ns
I0813 18:00:59.898775 27097 leveldb.cpp:204] Seeked to beginning of db in 19404ns
I0813 18:00:59.898829 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 29147ns
I0813 18:00:59.898888 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.899489 27119 recover.cpp:449] Starting replica recovery
I0813 18:00:59.899799 27123 recover.cpp:475] Replica is in VOTING status
I0813 18:00:59.899953 27123 recover.cpp:464] Recover process terminated
I0813 18:00:59.902916 27120 registrar.cpp:311] Recovering registrar
[       OK ] Strict/RegistrarTest.FetchTimeout/1 (55 ms)
[ RUN      ] Strict/RegistrarTest.StoreTimeout/0
Using temporary directory '/tmp/Strict_RegistrarTest_StoreTimeout_0_LjnuX4'
I0813 18:00:59.931071 27097 leveldb.cpp:176] Opened db in 3.042176ms
I0813 18:00:59.931990 27097 leveldb.cpp:183] Compacted db in 879281ns
I0813 18:00:59.932034 27097 leveldb.cpp:198] Created db iterator in 12775ns
I0813 18:00:59.932049 27097 leveldb.cpp:204] Seeked to beginning of db in 1383ns
I0813 18:00:59.932060 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 277ns
I0813 18:00:59.932091 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.932960 27131 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 423312ns
I0813 18:00:59.932991 27131 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.936257 27097 leveldb.cpp:176] Opened db in 2.649587ms
I0813 18:00:59.937361 27097 leveldb.cpp:183] Compacted db in 1.061111ms
I0813 18:00:59.937417 27097 leveldb.cpp:198] Created db iterator in 14110ns
I0813 18:00:59.937438 27097 leveldb.cpp:204] Seeked to beginning of db in 1755ns
I0813 18:00:59.937448 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 165ns
I0813 18:00:59.937489 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.938429 27126 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 458223ns
I0813 18:00:59.938460 27126 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.941510 27097 leveldb.cpp:176] Opened db in 2.492396ms
I0813 18:00:59.944128 27097 leveldb.cpp:183] Compacted db in 2.577304ms
I0813 18:00:59.944187 27097 leveldb.cpp:198] Created db iterator in 17925ns
I0813 18:00:59.944226 27097 leveldb.cpp:204] Seeked to beginning of db in 18482ns
I0813 18:00:59.944268 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 25917ns
I0813 18:00:59.944344 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.947232 27097 leveldb.cpp:176] Opened db in 2.695198ms
I0813 18:00:59.950215 27097 leveldb.cpp:183] Compacted db in 2.943043ms
I0813 18:00:59.950278 27097 leveldb.cpp:198] Created db iterator in 18937ns
I0813 18:00:59.950343 27097 leveldb.cpp:204] Seeked to beginning of db in 45121ns
I0813 18:00:59.950387 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 23904ns
I0813 18:00:59.950425 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.950899 27124 recover.cpp:449] Starting replica recovery
I0813 18:00:59.951285 27122 recover.cpp:475] Replica is in VOTING status
I0813 18:00:59.951458 27122 recover.cpp:464] Recover process terminated
I0813 18:00:59.953532 27124 registrar.cpp:311] Recovering registrar
I0813 18:00:59.956615 27124 registrar.cpp:344] Successfully fetched the registry (0B) in 0ns
I0813 18:00:59.956722 27124 registrar.cpp:443] Applied 1 operations in 23814ns; attempting to update the 'registry'
E0813 18:00:59.964251 27118 registrar.cpp:510] Registrar aborting: Failed to update 'registry': Failed to perform store within 10secs
[       OK ] Strict/RegistrarTest.StoreTimeout/0 (51 ms)
[ RUN      ] Strict/RegistrarTest.StoreTimeout/1
Using temporary directory '/tmp/Strict_RegistrarTest_StoreTimeout_1_qGnk1M'
I0813 18:00:59.981770 27097 leveldb.cpp:176] Opened db in 2.847776ms
I0813 18:00:59.982787 27097 leveldb.cpp:183] Compacted db in 980419ns
I0813 18:00:59.982836 27097 leveldb.cpp:198] Created db iterator in 13655ns
I0813 18:00:59.982861 27097 leveldb.cpp:204] Seeked to beginning of db in 1695ns
I0813 18:00:59.982872 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 182ns
I0813 18:00:59.982904 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.983865 27118 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 688534ns
I0813 18:00:59.983903 27118 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.987309 27097 leveldb.cpp:176] Opened db in 2.712145ms
I0813 18:00:59.988404 27097 leveldb.cpp:183] Compacted db in 1.037609ms
I0813 18:00:59.988459 27097 leveldb.cpp:198] Created db iterator in 14020ns
I0813 18:00:59.988483 27097 leveldb.cpp:204] Seeked to beginning of db in 1773ns
I0813 18:00:59.988494 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 165ns
I0813 18:00:59.988525 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.989332 27121 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 533023ns
I0813 18:00:59.989363 27121 replica.cpp:323] Persisted replica status to VOTING
I0813 18:00:59.992429 27097 leveldb.cpp:176] Opened db in 2.545834ms
I0813 18:00:59.995609 27097 leveldb.cpp:183] Compacted db in 3.138141ms
I0813 18:00:59.995671 27097 leveldb.cpp:198] Created db iterator in 18942ns
I0813 18:00:59.995709 27097 leveldb.cpp:204] Seeked to beginning of db in 18967ns
I0813 18:00:59.995745 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 20904ns
I0813 18:00:59.995784 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:00:59.999143 27097 leveldb.cpp:176] Opened db in 3.165713ms
I0813 18:01:00.002497 27097 leveldb.cpp:183] Compacted db in 3.313371ms
I0813 18:01:00.002562 27097 leveldb.cpp:198] Created db iterator in 19452ns
I0813 18:01:00.002600 27097 leveldb.cpp:204] Seeked to beginning of db in 19097ns
I0813 18:01:00.002637 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 22334ns
I0813 18:01:00.002676 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.003209 27117 recover.cpp:449] Starting replica recovery
I0813 18:01:00.003422 27117 recover.cpp:475] Replica is in VOTING status
I0813 18:01:00.003566 27117 recover.cpp:464] Recover process terminated
I0813 18:01:00.006894 27119 registrar.cpp:311] Recovering registrar
I0813 18:01:00.009877 27119 registrar.cpp:344] Successfully fetched the registry (0B) in 0ns
I0813 18:01:00.009985 27119 registrar.cpp:443] Applied 1 operations in 21921ns; attempting to update the 'registry'
E0813 18:01:00.017173 27125 registrar.cpp:510] Registrar aborting: Failed to update 'registry': Failed to perform store within 10secs
[       OK ] Strict/RegistrarTest.StoreTimeout/1 (52 ms)
[ RUN      ] Strict/RegistrarTest.Abort/0
Using temporary directory '/tmp/Strict_RegistrarTest_Abort_0_nukMdv'
I0813 18:01:00.035025 27097 leveldb.cpp:176] Opened db in 3.062886ms
I0813 18:01:00.036001 27097 leveldb.cpp:183] Compacted db in 937322ns
I0813 18:01:00.036049 27097 leveldb.cpp:198] Created db iterator in 13764ns
I0813 18:01:00.036070 27097 leveldb.cpp:204] Seeked to beginning of db in 1667ns
I0813 18:01:00.036082 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 185ns
I0813 18:01:00.036113 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.037346 27118 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 716920ns
I0813 18:01:00.037384 27118 replica.cpp:323] Persisted replica status to VOTING
I0813 18:01:00.041075 27097 leveldb.cpp:176] Opened db in 2.98693ms
I0813 18:01:00.042054 27097 leveldb.cpp:183] Compacted db in 940172ns
I0813 18:01:00.042104 27097 leveldb.cpp:198] Created db iterator in 14807ns
I0813 18:01:00.042124 27097 leveldb.cpp:204] Seeked to beginning of db in 1495ns
I0813 18:01:00.042135 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 160ns
I0813 18:01:00.042167 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.043505 27123 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 646763ns
I0813 18:01:00.043542 27123 replica.cpp:323] Persisted replica status to VOTING
I0813 18:01:00.047478 27097 leveldb.cpp:176] Opened db in 3.410889ms
I0813 18:01:00.050539 27097 leveldb.cpp:183] Compacted db in 3.019957ms
I0813 18:01:00.050601 27097 leveldb.cpp:198] Created db iterator in 19282ns
I0813 18:01:00.050639 27097 leveldb.cpp:204] Seeked to beginning of db in 20242ns
I0813 18:01:00.050675 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 21717ns
I0813 18:01:00.050711 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.053953 27097 leveldb.cpp:176] Opened db in 3.060909ms
I0813 18:01:00.056818 27097 leveldb.cpp:183] Compacted db in 2.822982ms
I0813 18:01:00.056877 27097 leveldb.cpp:198] Created db iterator in 19217ns
I0813 18:01:00.056915 27097 leveldb.cpp:204] Seeked to beginning of db in 19340ns
I0813 18:01:00.056951 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 20672ns
I0813 18:01:00.056988 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.057494 27127 recover.cpp:449] Starting replica recovery
I0813 18:01:00.057737 27127 recover.cpp:475] Replica is in VOTING status
I0813 18:01:00.057899 27127 recover.cpp:464] Recover process terminated
I0813 18:01:00.060782 27119 registrar.cpp:311] Recovering registrar
I0813 18:01:00.064206 27119 registrar.cpp:344] Successfully fetched the registry (0B) in 3.372032ms
I0813 18:01:00.064327 27119 registrar.cpp:443] Applied 1 operations in 21549ns; attempting to update the 'registry'
I0813 18:01:00.067538 27119 registrar.cpp:488] Successfully updated the 'registry' in 3.14496ms
I0813 18:01:00.067694 27119 registrar.cpp:374] Successfully recovered registrar
I0813 18:01:00.068501 27119 registrar.cpp:443] Applied 1 operations in 39479ns; attempting to update the 'registry'
E0813 18:01:00.071552 27119 registrar.cpp:510] Registrar aborting: Failed to update 'registry': failure
[       OK ] Strict/RegistrarTest.Abort/0 (45 ms)
[ RUN      ] Strict/RegistrarTest.Abort/1
Using temporary directory '/tmp/Strict_RegistrarTest_Abort_1_m3Lpxd'
I0813 18:01:00.079236 27097 leveldb.cpp:176] Opened db in 3.069713ms
I0813 18:01:00.080219 27097 leveldb.cpp:183] Compacted db in 945064ns
I0813 18:01:00.080266 27097 leveldb.cpp:198] Created db iterator in 13329ns
I0813 18:01:00.080281 27097 leveldb.cpp:204] Seeked to beginning of db in 1525ns
I0813 18:01:00.080292 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 162ns
I0813 18:01:00.080343 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.081343 27120 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 541853ns
I0813 18:01:00.081377 27120 replica.cpp:323] Persisted replica status to VOTING
I0813 18:01:00.084305 27097 leveldb.cpp:176] Opened db in 2.416643ms
I0813 18:01:00.085175 27097 leveldb.cpp:183] Compacted db in 805604ns
I0813 18:01:00.085232 27097 leveldb.cpp:198] Created db iterator in 15763ns
I0813 18:01:00.085258 27097 leveldb.cpp:204] Seeked to beginning of db in 1865ns
I0813 18:01:00.085276 27097 leveldb.cpp:273] Iterated through 0 keys in the db in 290ns
I0813 18:01:00.085345 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.086402 27118 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 503157ns
I0813 18:01:00.086436 27118 replica.cpp:323] Persisted replica status to VOTING
I0813 18:01:00.089941 27097 leveldb.cpp:176] Opened db in 2.856357ms
I0813 18:01:00.093217 27097 leveldb.cpp:183] Compacted db in 3.233141ms
I0813 18:01:00.093291 27097 leveldb.cpp:198] Created db iterator in 22502ns
I0813 18:01:00.093394 27097 leveldb.cpp:204] Seeked to beginning of db in 82563ns
I0813 18:01:00.093447 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 30930ns
I0813 18:01:00.093490 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.096662 27097 leveldb.cpp:176] Opened db in 2.990233ms
I0813 18:01:00.099722 27097 leveldb.cpp:183] Compacted db in 3.019507ms
I0813 18:01:00.099782 27097 leveldb.cpp:198] Created db iterator in 19264ns
I0813 18:01:00.099820 27097 leveldb.cpp:204] Seeked to beginning of db in 20004ns
I0813 18:01:00.099856 27097 leveldb.cpp:273] Iterated through 1 keys in the db in 20949ns
I0813 18:01:00.099894 27097 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 18:01:00.100404 27121 recover.cpp:449] Starting replica recovery
I0813 18:01:00.100639 27121 recover.cpp:475] Replica is in VOTING status
I0813 18:01:00.100790 27121 recover.cpp:464] Recover process terminated
I0813 18:01:00.103438 27119 registrar.cpp:311] Recovering registrar
I0813 18:01:00.106487 27119 registrar.cpp:344] Successfully fetched the registry (0B) in 2.872064ms
I0813 18:01:00.106591 27119 registrar.cpp:443] Applied 1 operations in 19735ns; attempting to update the 'registry'
I0813 18:01:00.110139 27119 registrar.cpp:488] Successfully updated the 'registry' in 3.47904ms
I0813 18:01:00.110265 27119 registrar.cpp:374] Successfully recovered registrar
I0813 18:01:00.111085 27121 registrar.cpp:443] Applied 1 operations in 50891ns; attempting to update the 'registry'
E0813 18:01:00.113780 27121 registrar.cpp:510] Registrar aborting: Failed to update 'registry': failure
[       OK ] Strict/RegistrarTest.Abort/1 (42 ms)
[----------] 16 tests from Strict/RegistrarTest (1131 ms total)

[----------] Global test environment tear-down
[==========] 704 tests from 99 test cases ran. (297709 ms total)
[  PASSED  ] 703 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] SchedulerTest.Revive

 1 FAILED TEST
  YOU HAVE 8 DISABLED TESTS

make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.24.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1439487492-16422
Untagged: mesos-1439487492-16422:latest
Deleted: a541dee3305bf5ca8abfab48750013174bb5ce57f1a71ded080bbc808b1a6777
Deleted: b044def6014d6734e18dbd4664ebd5ee39f39da422bf08db9fbed5ae69aa0eff
Deleted: eab26368a8b243a04b5f8bf9b3f7486cdc438320fcd1ff4a27000db4927ede19
Deleted: 806eed38ec2ef8864060e0af572f834442752c5bb182d3a5e9a3b37443434f24
Deleted: 8ac0cadfea08395a852d195317df1155a3fbd8e6d4c43067e5563fc25edf1c5d
Deleted: 0e3923b664dcb97eedf711ba01c77c7d998de2f02b2587ad9e4f7765f594a062
Deleted: 7ac414c13f03ecd0b0cc3c73678c99f8eabb28f792ab4701c58bbefe2f15aa4a
Deleted: c3b98cf2df0fa07fd79c17717f8ddabcc061e9a6c7264de368c885785546fd7e
Deleted: 0a101a1afa15d79ce6b09a40315f0ef695492b3139906f0d4409e38e4079241c
Deleted: c60bebff644b31001040360c88d44a1f8e78c8999d24b036f5144e090db9af5f
Deleted: 035ad706f75e0a788134ea4964254245d219e39b381724dd5e437edd4ff6acc5
Deleted: 7257527774b5114c595b294e104a23b827a322c14e989b9ebd47054f22f1aaa3
Build step 'Execute shell' marked build as failure

Jenkins build is back to normal : Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #706

Posted by Apache Jenkins Server <je...@builds.apache.org>.

See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/706/changes>

Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #705

Posted by Apache Jenkins Server <je...@builds.apache.org>.

See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/705/changes>

Changes:

[benjamin.mahler] Updated /scheduler endopint to use Request::acceptsMediaType.

[benjamin.mahler] Removed unnecessary std:: prefix in http_api_tests.cpp.

[benjamin.mahler] Ensure the Content-Type is set for the streaming scheduler endpoint.

[benjamin.mahler] Only accept POST requests for /scheduler endpoint.

------------------------------------------
[...truncated 85223 lines...]
Value of: event.get().type()
  Actual: HEARTBEAT
Expected: Event::OFFERS
Which is: OFFERS
../../src/tests/scheduler_tests.cpp:228: Failure
Expected: (0) != (event.get().offers().offers().size()), actual: 0 vs 0
I0813 20:00:42.606860 27116 log.cpp:685] Attempting to append 341 bytes to the log
[libprotobuf FATAL ../3rdparty/libprocess/3rdparty/protobuf-2.5.0/src/google/protobuf/repeated_field.h:824] CHECK failed: (index) < (size()): 
I0813 20:00:42.607162 27120 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
../../src/tests/scheduler_tests.cpp:237: Failure
Actual function call count doesn't match EXPECT_CALL(containerizer, update(_, _))...
         Expected: to be called at least once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:233: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:230: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
unknown file: Failure
C++ exception with description "CHECK failed: (index) < (size()): " thrown in the test body.
I0813 20:00:42.609213 27122 replica.cpp:511] Replica received write request for position 3
I0813 20:00:42.609225 27117 slave.cpp:1209] Will retry registration in 26.60588ms if necessary
I0813 20:00:42.609217 27113 master.cpp:859] Master terminating
I0813 20:00:42.609442 27108 hierarchical.hpp:428] Removed framework 20150813-200042-151130540-54398-27089-0000
I0813 20:00:42.609777 27122 leveldb.cpp:343] Persisting action (360 bytes) to leveldb took 517601ns
I0813 20:00:42.609812 27122 replica.cpp:679] Persisted action at 3
I0813 20:00:42.610157 27109 slave.cpp:3143] master@172.17.2.9:54398 exited
W0813 20:00:42.610195 27109 slave.cpp:3146] Master disconnected! Waiting for a new master to be elected
I0813 20:00:42.611116 27122 replica.cpp:658] Replica received learned notice for position 3
I0813 20:00:42.611507 27122 leveldb.cpp:343] Persisting action (362 bytes) to leveldb took 355098ns
I0813 20:00:42.611538 27122 replica.cpp:679] Persisted action at 3
I0813 20:00:42.611559 27122 replica.cpp:664] Replica learned APPEND action at position 3
[  FAILED  ] SchedulerTest.TaskRunning (70 ms)
[ RUN      ] SchedulerTest.ReconcileTask
Using temporary directory '/tmp/SchedulerTest_ReconcileTask_yFYxDQ'
I0813 20:00:42.619635 27089 leveldb.cpp:176] Opened db in 2.832412ms
I0813 20:00:42.620666 27089 leveldb.cpp:183] Compacted db in 990274ns
I0813 20:00:42.620719 27089 leveldb.cpp:198] Created db iterator in 18148ns
I0813 20:00:42.620740 27089 leveldb.cpp:204] Seeked to beginning of db in 1958ns
I0813 20:00:42.620751 27089 leveldb.cpp:273] Iterated through 0 keys in the db in 268ns
I0813 20:00:42.620787 27089 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 20:00:42.621337 27123 recover.cpp:449] Starting replica recovery
I0813 20:00:42.621711 27121 recover.cpp:475] Replica is in EMPTY status
I0813 20:00:42.622890 27123 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0813 20:00:42.623292 27120 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0813 20:00:42.623718 27123 recover.cpp:566] Updating replica status to STARTING
I0813 20:00:42.624054 27118 master.cpp:378] Master 20150813-200042-151130540-54398-27089 (23baf00bc1c5) started on 172.17.2.9:54398
I0813 20:00:42.624080 27118 master.cpp:380] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --credentials="/tmp/SchedulerTest_ReconcileTask_yFYxDQ/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.24.0/_inst/share/mesos/webui" --work_dir="/tmp/SchedulerTest_ReconcileTask_yFYxDQ/master" --zk_session_timeout="10secs"
I0813 20:00:42.624325 27118 master.cpp:427] Master allowing unauthenticated frameworks to register
I0813 20:00:42.624336 27118 master.cpp:430] Master only allowing authenticated slaves to register
I0813 20:00:42.624341 27118 credentials.hpp:37] Loading credentials for authentication from '/tmp/SchedulerTest_ReconcileTask_yFYxDQ/credentials'
I0813 20:00:42.624517 27119 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 599681ns
I0813 20:00:42.624542 27119 replica.cpp:323] Persisted replica status to STARTING
I0813 20:00:42.624548 27118 master.cpp:469] Using default 'crammd5' authenticator
I0813 20:00:42.624644 27118 master.cpp:506] Authorization enabled
I0813 20:00:42.624717 27120 recover.cpp:475] Replica is in STARTING status
I0813 20:00:42.624801 27117 whitelist_watcher.cpp:79] No whitelist given
I0813 20:00:42.624867 27113 hierarchical.hpp:346] Initialized hierarchical allocator process
I0813 20:00:42.625814 27112 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0813 20:00:42.625866 27121 master.cpp:1524] The newly elected leader is master@172.17.2.9:54398 with id 20150813-200042-151130540-54398-27089
I0813 20:00:42.625912 27121 master.cpp:1537] Elected as the leading master!
I0813 20:00:42.625941 27121 master.cpp:1307] Recovering from registrar
I0813 20:00:42.626124 27109 recover.cpp:195] Received a recover response from a replica in STARTING status
I0813 20:00:42.626245 27123 registrar.cpp:311] Recovering registrar
I0813 20:00:42.626689 27108 recover.cpp:566] Updating replica status to VOTING
I0813 20:00:42.627406 27123 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 350151ns
I0813 20:00:42.627437 27123 replica.cpp:323] Persisted replica status to VOTING
I0813 20:00:42.627563 27110 recover.cpp:580] Successfully joined the Paxos group
I0813 20:00:42.627799 27110 recover.cpp:464] Recover process terminated
I0813 20:00:42.628294 27113 log.cpp:661] Attempting to start the writer
I0813 20:00:42.629655 27110 replica.cpp:477] Replica received implicit promise request with proposal 1
I0813 20:00:42.630053 27110 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 364833ns
I0813 20:00:42.630089 27110 replica.cpp:345] Persisted promised to 1
I0813 20:00:42.630880 27120 coordinator.cpp:231] Coordinator attemping to fill missing position
I0813 20:00:42.632082 27117 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0813 20:00:42.632480 27117 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 361290ns
I0813 20:00:42.632503 27117 replica.cpp:679] Persisted action at 0
I0813 20:00:42.633635 27119 replica.cpp:511] Replica received write request for position 0
I0813 20:00:42.633703 27119 leveldb.cpp:438] Reading position from leveldb took 34444ns
I0813 20:00:42.634188 27119 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 429349ns
I0813 20:00:42.634225 27119 replica.cpp:679] Persisted action at 0
I0813 20:00:42.634928 27114 replica.cpp:658] Replica received learned notice for position 0
I0813 20:00:42.635445 27114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 481162ns
I0813 20:00:42.635476 27114 replica.cpp:679] Persisted action at 0
I0813 20:00:42.635499 27114 replica.cpp:664] Replica learned NOP action at position 0
I0813 20:00:42.636252 27115 log.cpp:677] Writer started with ending position 0
I0813 20:00:42.637204 27111 slave.cpp:1209] Will retry registration in 58.281296ms if necessary
I0813 20:00:42.637236 27108 master.cpp:1134] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
I0813 20:00:42.637588 27109 leveldb.cpp:438] Reading position from leveldb took 34754ns
I0813 20:00:42.641024 27112 registrar.cpp:344] Successfully fetched the registry (0B) in 14.511872ms
I0813 20:00:42.641161 27112 registrar.cpp:443] Applied 1 operations in 29360ns; attempting to update the 'registry'
I0813 20:00:42.644320 27109 log.cpp:685] Attempting to append 171 bytes to the log
I0813 20:00:42.644551 27111 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I0813 20:00:42.645483 27118 replica.cpp:511] Replica received write request for position 1
I0813 20:00:42.646026 27118 leveldb.cpp:343] Persisting action (190 bytes) to leveldb took 501762ns
I0813 20:00:42.646061 27118 replica.cpp:679] Persisted action at 1
I0813 20:00:42.646828 27109 replica.cpp:658] Replica received learned notice for position 1
I0813 20:00:42.647209 27109 leveldb.cpp:343] Persisting action (192 bytes) to leveldb took 349781ns
I0813 20:00:42.647241 27109 replica.cpp:679] Persisted action at 1
I0813 20:00:42.647264 27109 replica.cpp:664] Replica learned APPEND action at position 1
I0813 20:00:42.648500 27116 registrar.cpp:488] Successfully updated the 'registry' in 7.265024ms
I0813 20:00:42.648669 27116 registrar.cpp:374] Successfully recovered registrar
I0813 20:00:42.648735 27115 log.cpp:704] Attempting to truncate the log to 1
I0813 20:00:42.648860 27108 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I0813 20:00:42.649173 27122 master.cpp:1334] Recovered 0 slaves from the Registry (132B) ; allowing 10mins for slaves to re-register
I0813 20:00:42.649972 27121 replica.cpp:511] Replica received write request for position 2
I0813 20:00:42.650486 27121 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 416906ns
I0813 20:00:42.650518 27121 replica.cpp:679] Persisted action at 2
I0813 20:00:42.651274 27123 replica.cpp:658] Replica received learned notice for position 2
I0813 20:00:42.651698 27123 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 337201ns
I0813 20:00:42.651777 27123 leveldb.cpp:401] Deleting ~1 keys from leveldb took 44377ns
I0813 20:00:42.651810 27123 replica.cpp:679] Persisted action at 2
I0813 20:00:42.651847 27123 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0813 20:00:42.665180 27110 slave.cpp:190] Slave started on 212)@172.17.2.9:54398
I0813 20:00:42.665212 27110 slave.cpp:191] Flags at startup: --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/SchedulerTest_ReconcileTask_lmwNEx/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SchedulerTest_ReconcileTask_lmwNEx/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.24.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/SchedulerTest_ReconcileTask_lmwNEx"
I0813 20:00:42.665722 27110 credentials.hpp:85] Loading credential for authentication from '/tmp/SchedulerTest_ReconcileTask_lmwNEx/credential'
I0813 20:00:42.665964 27110 slave.cpp:321] Slave using credential for: test-principal
I0813 20:00:42.666393 27089 scheduler.cpp:157] Version: 0.24.0
I0813 20:00:42.666576 27110 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0813 20:00:42.666705 27110 slave.cpp:384] Slave hostname: 23baf00bc1c5
I0813 20:00:42.666729 27110 slave.cpp:389] Slave checkpoint: true
I0813 20:00:42.667490 27120 state.cpp:54] Recovering state from '/tmp/SchedulerTest_ReconcileTask_lmwNEx/meta'
I0813 20:00:42.667778 27115 status_update_manager.cpp:202] Recovering status update manager
I0813 20:00:42.668107 27108 slave.cpp:4069] Finished recovery
I0813 20:00:42.668560 27108 slave.cpp:4226] Querying resource estimator for oversubscribable resources
I0813 20:00:42.668844 27109 slave.cpp:684] New master detected at master@172.17.2.9:54398
I0813 20:00:42.668841 27121 scheduler.cpp:272] New master detected at master@172.17.2.9:54398
I0813 20:00:42.668850 27120 status_update_manager.cpp:176] Pausing sending status updates
I0813 20:00:42.668972 27109 slave.cpp:747] Authenticating with master master@172.17.2.9:54398
I0813 20:00:42.669011 27109 slave.cpp:752] Using default CRAM-MD5 authenticatee
I0813 20:00:42.669147 27109 slave.cpp:720] Detecting new master
I0813 20:00:42.669215 27117 authenticatee.cpp:115] Creating new client SASL connection
I0813 20:00:42.669437 27109 slave.cpp:4240] Received oversubscribable resources  from the resource estimator
I0813 20:00:42.669478 27112 master.cpp:4693] Authenticating slave(212)@172.17.2.9:54398
I0813 20:00:42.669647 27123 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(515)@172.17.2.9:54398
I0813 20:00:42.669891 27114 authenticator.cpp:92] Creating new server SASL connection
I0813 20:00:42.670202 27119 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I0813 20:00:42.670229 27119 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 20:00:42.670341 27116 authenticator.cpp:197] Received SASL authentication start
I0813 20:00:42.670387 27116 authenticator.cpp:319] Authentication requires more steps
I0813 20:00:42.670472 27116 authenticatee.cpp:252] Received SASL authentication step
I0813 20:00:42.670570 27115 authenticator.cpp:225] Received SASL authentication step
I0813 20:00:42.670603 27115 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23baf00bc1c5' server FQDN: '23baf00bc1c5' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 20:00:42.670614 27115 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0813 20:00:42.670655 27115 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 20:00:42.670680 27115 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23baf00bc1c5' server FQDN: '23baf00bc1c5' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 20:00:42.670687 27115 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 20:00:42.670694 27115 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 20:00:42.670712 27115 authenticator.cpp:311] Authentication success
I0813 20:00:42.670789 27116 authenticatee.cpp:292] Authentication success
I0813 20:00:42.670845 27112 master.cpp:4723] Successfully authenticated principal 'test-principal' at slave(212)@172.17.2.9:54398
I0813 20:00:42.670869 27115 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(515)@172.17.2.9:54398
I0813 20:00:42.671094 27116 slave.cpp:815] Successfully authenticated with master master@172.17.2.9:54398
I0813 20:00:42.671191 27116 slave.cpp:1209] Will retry registration in 18.615907ms if necessary
I0813 20:00:42.671371 27123 master.cpp:3635] Registering slave at slave(212)@172.17.2.9:54398 (23baf00bc1c5) with id 20150813-200042-151130540-54398-27089-S0
I0813 20:00:42.671628 27123 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0813 20:00:42.671814 27121 registrar.cpp:443] Applied 1 operations in 73325ns; attempting to update the 'registry'
I0813 20:00:42.672034 27123 master.cpp:1782] Received subscription request for HTTP framework 'default'
I0813 20:00:42.672113 27123 master.cpp:1563] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0813 20:00:42.672386 27123 master.cpp:1874] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I0813 20:00:42.672750 27111 hierarchical.hpp:391] Added framework 20150813-200042-151130540-54398-27089-0000
I0813 20:00:42.672787 27111 hierarchical.hpp:1008] No resources available to allocate!
I0813 20:00:42.672801 27111 hierarchical.hpp:908] Performed allocation for 0 slaves in 21227ns
I0813 20:00:42.672837 27119 master.hpp:1305] Sending heartbeat to 20150813-200042-151130540-54398-27089-0000
I0813 20:00:42.675727 27115 log.cpp:685] Attempting to append 341 bytes to the log
[libprotobuf FATAL ../3rdparty/libprocess/3rdparty/protobuf-2.5.0/src/google/protobuf/repeated_field.h:824] CHECK failed: (index) < (size()): 
../../src/tests/scheduler_tests.cpp:337: Failure
Value of: event.get().type()
  Actual: HEARTBEAT
Expected: Event::OFFERS
Which is: OFFERS
../../src/tests/scheduler_tests.cpp:338: Failure
Expected: (0) != (event.get().offers().offers().size()), actual: 0 vs 0
I0813 20:00:42.676072 27118 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
../../src/tests/scheduler_tests.cpp:343: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:340: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
unknown file: Failure
C++ exception with description "CHECK failed: (index) < (size()): " thrown in the test body.
I0813 20:00:42.677289 27112 replica.cpp:511] Replica received write request for position 3
I0813 20:00:42.677821 27112 leveldb.cpp:343] Persisting action (360 bytes) to leveldb took 488382ns
I0813 20:00:42.677855 27112 replica.cpp:679] Persisted action at 3
I0813 20:00:42.678057 27109 master.cpp:859] Master terminating
I0813 20:00:42.678473 27110 hierarchical.hpp:428] Removed framework 20150813-200042-151130540-54398-27089-0000
I0813 20:00:42.678843 27111 replica.cpp:658] Replica received learned notice for position 3
I0813 20:00:42.679287 27110 slave.cpp:3143] master@172.17.2.9:54398 exited
W0813 20:00:42.679321 27110 slave.cpp:3146] Master disconnected! Waiting for a new master to be elected
I0813 20:00:42.679424 27111 leveldb.cpp:343] Persisting action (362 bytes) to leveldb took 546515ns
I0813 20:00:42.679461 27111 replica.cpp:679] Persisted action at 3
I0813 20:00:42.679497 27111 replica.cpp:664] Replica learned APPEND action at position 3
I0813 20:00:42.681294 27121 registrar.cpp:488] Successfully updated the 'registry' in 9.374208ms
I0813 20:00:42.681584 27114 log.cpp:704] Attempting to truncate the log to 3
I0813 20:00:42.681730 27119 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
I0813 20:00:42.683099 27114 replica.cpp:511] Replica received write request for position 4
I0813 20:00:42.683480 27114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 348969ns
I0813 20:00:42.683506 27114 replica.cpp:679] Persisted action at 4
*** Aborted at 1439496042 (unix time) try "date -d @1439496042" if you are using GNU date ***
PC: @           0x8e26c0 mesos::internal::tests::Cluster::Slaves::shutdown()
I0813 20:00:42.690062 27117 slave.cpp:1209] Will retry registration in 22.716087ms if necessary
I0813 20:00:42.696158 27112 slave.cpp:1209] Will retry registration in 105.654802ms if necessary
I0813 20:00:42.713459 27119 slave.cpp:1209] Will retry registration in 40.030296ms if necessary
I0813 20:00:42.753821 27108 slave.cpp:1209] Will retry registration in 98.694199ms if necessary
*** SIGSEGV (@0x0) received by PID 27089 (TID 0x2b24d82e3bc0) from PID 0; stack trace: ***
    @     0x2b24ee7b7867 os::Linux::chained_handler()
    @     0x2b24ee7bbaf9 JVM_handle_linux_signal
    @     0x2b24de214340 (unknown)
    @           0x8e26c0 mesos::internal::tests::Cluster::Slaves::shutdown()
    @           0xe2decc mesos::internal::tests::MesosTest::ShutdownSlaves()
    @           0xe2de8e mesos::internal::tests::MesosTest::Shutdown()
    @           0xe2a437 mesos::internal::tests::MesosTest::TearDown()
I0813 20:00:42.803058 27123 slave.cpp:1209] Will retry registration in 10.790417ms if necessary
    @          0x132d216 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
    @          0x132808c testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x130984c testing::Test::Run()
    @          0x1309f86 testing::TestInfo::Run()
I0813 20:00:42.814385 27109 slave.cpp:1209] Will retry registration in 187.681354ms if necessary
    @          0x130a5cc testing::TestCase::Run()
    @          0x1310d14 testing::internal::UnitTestImpl::RunAllTests()
    @          0x132de3b testing::internal::HandleSehExceptionsInMethodIfSupported<>()
    @          0x1328c02 testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x130fab0 testing::UnitTest::Run()
    @           0xc96d97 RUN_ALL_TESTS()
    @           0xc96a9b main
    @     0x2b24de443ec5 (unknown)
    @           0x8d86c9 (unknown)
make[4]: *** [check-local] Segmentation fault
make[4]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.24.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1439494769-18771
Untagged: mesos-1439494769-18771:latest
Deleted: 2a61bf4c02a1e29e69a954f574d255da36a72518ca9c2290c56c2e354a15fbfc
Deleted: 786de0faf6fba92cb900b6d80472a95ed376489afd048244f204dcf24ef4c408
Deleted: 0d42a572659e835f2847588105b899944aa6aaa27fa25c17b8619732b4f08527
Deleted: d7af74fa86c0e2277840eaf13a6b4bfd11f165be071aab00b1f060d5a3bd2522
Build step 'Execute shell' marked build as failure

Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #704

Posted by Apache Jenkins Server <je...@builds.apache.org>.

See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/704/changes>

Changes:

[vinodkone] Added Heartbeater to master to send periodic heartbeats to HTTP schedulers.

[vinodkone] Fixed style issue in master/main.cpp.

------------------------------------------
[...truncated 88259 lines...]
I0813 19:22:05.700361 27125 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 19:22:05.700383 27125 authenticator.cpp:311] Authentication success
I0813 19:22:05.700489 27112 authenticatee.cpp:292] Authentication success
I0813 19:22:05.700554 27125 master.cpp:4723] Successfully authenticated principal 'test-principal' at slave(211)@172.17.2.67:42492
I0813 19:22:05.700619 27117 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(514)@172.17.2.67:42492
I0813 19:22:05.700969 27113 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0813 19:22:05.701113 27121 slave.cpp:815] Successfully authenticated with master master@172.17.2.67:42492
I0813 19:22:05.701230 27121 slave.cpp:1209] Will retry registration in 15.546443ms if necessary
I0813 19:22:05.701350 27113 master.cpp:1782] Received subscription request for HTTP framework 'default'
I0813 19:22:05.701418 27113 master.cpp:1563] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0813 19:22:05.701743 27113 master.cpp:3635] Registering slave at slave(211)@172.17.2.67:42492 (e0a808ab0d7c) with id 20150813-192205-1124209068-42492-27093-S0
I0813 19:22:05.702162 27113 master.cpp:1874] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I0813 19:22:05.702357 27126 registrar.cpp:443] Applied 1 operations in 61028ns; attempting to update the 'registry'
I0813 19:22:05.702574 27119 hierarchical.hpp:391] Added framework 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.702602 27113 master.hpp:1305] Sending heartbeat to 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.702605 27119 hierarchical.hpp:1008] No resources available to allocate!
I0813 19:22:05.702641 27119 hierarchical.hpp:908] Performed allocation for 0 slaves in 42286ns
../../src/tests/scheduler_tests.cpp:227: Failure
Value of: event.get().type()
  Actual: HEARTBEAT
Expected: Event::OFFERS
Which is: OFFERS
../../src/tests/scheduler_tests.cpp:228: Failure
Expected: (0) != (event.get().offers().offers().size()), actual: 0 vs 0
I0813 19:22:05.705129 27115 log.cpp:685] Attempting to append 347 bytes to the log
[libprotobuf FATAL ../3rdparty/libprocess/3rdparty/protobuf-2.5.0/src/google/protobuf/repeated_field.h:824] CHECK failed: (index) < (size()): 
I0813 19:22:05.705243 27112 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
../../src/tests/scheduler_tests.cpp:237: Failure
Actual function call count doesn't match EXPECT_CALL(containerizer, update(_, _))...
         Expected: to be called at least once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:233: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:230: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
unknown file: Failure
C++ exception with description "CHECK failed: (index) < (size()): " thrown in the test body.
I0813 19:22:05.706290 27122 replica.cpp:511] Replica received write request for position 3
I0813 19:22:05.706867 27122 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 541708ns
I0813 19:22:05.706892 27122 replica.cpp:679] Persisted action at 3
I0813 19:22:05.706941 27093 master.cpp:859] Master terminating
I0813 19:22:05.707118 27116 hierarchical.hpp:428] Removed framework 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.708087 27118 slave.cpp:3143] master@172.17.2.67:42492 exited
W0813 19:22:05.708119 27118 slave.cpp:3146] Master disconnected! Waiting for a new master to be elected
I0813 19:22:05.708235 27124 replica.cpp:658] Replica received learned notice for position 3
I0813 19:22:05.708688 27124 leveldb.cpp:343] Persisting action (368 bytes) to leveldb took 426170ns
I0813 19:22:05.708717 27124 replica.cpp:679] Persisted action at 3
I0813 19:22:05.708740 27124 replica.cpp:664] Replica learned APPEND action at position 3
[  FAILED  ] SchedulerTest.TaskRunning (65 ms)
[ RUN      ] SchedulerTest.ReconcileTask
Using temporary directory '/tmp/SchedulerTest_ReconcileTask_ybAyRX'
I0813 19:22:05.716075 27093 leveldb.cpp:176] Opened db in 2.364385ms
I0813 19:22:05.716781 27093 leveldb.cpp:183] Compacted db in 665565ns
I0813 19:22:05.716835 27093 leveldb.cpp:198] Created db iterator in 30572ns
I0813 19:22:05.716848 27093 leveldb.cpp:204] Seeked to beginning of db in 1818ns
I0813 19:22:05.716856 27093 leveldb.cpp:273] Iterated through 0 keys in the db in 362ns
I0813 19:22:05.716897 27093 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0813 19:22:05.717170 27119 slave.cpp:1209] Will retry registration in 17.255336ms if necessary
I0813 19:22:05.717385 27119 recover.cpp:449] Starting replica recovery
I0813 19:22:05.717634 27112 recover.cpp:475] Replica is in EMPTY status
I0813 19:22:05.718533 27124 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0813 19:22:05.718863 27112 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0813 19:22:05.719521 27123 recover.cpp:566] Updating replica status to STARTING
I0813 19:22:05.720268 27124 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 597114ns
I0813 19:22:05.720293 27124 replica.cpp:323] Persisted replica status to STARTING
I0813 19:22:05.720454 27124 recover.cpp:475] Replica is in STARTING status
I0813 19:22:05.721259 27117 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0813 19:22:05.721462 27112 master.cpp:378] Master 20150813-192205-1124209068-42492-27093 (e0a808ab0d7c) started on 172.17.2.67:42492
I0813 19:22:05.721616 27118 recover.cpp:195] Received a recover response from a replica in STARTING status
I0813 19:22:05.721714 27112 master.cpp:380] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --credentials="/tmp/SchedulerTest_ReconcileTask_ybAyRX/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.24.0/_inst/share/mesos/webui" --work_dir="/tmp/SchedulerTest_ReconcileTask_ybAyRX/master" --zk_session_timeout="10secs"
I0813 19:22:05.722072 27112 master.cpp:427] Master allowing unauthenticated frameworks to register
I0813 19:22:05.722185 27112 master.cpp:430] Master only allowing authenticated slaves to register
I0813 19:22:05.722203 27112 credentials.hpp:37] Loading credentials for authentication from '/tmp/SchedulerTest_ReconcileTask_ybAyRX/credentials'
I0813 19:22:05.722215 27123 recover.cpp:566] Updating replica status to VOTING
I0813 19:22:05.722501 27112 master.cpp:469] Using default 'crammd5' authenticator
I0813 19:22:05.722638 27112 master.cpp:506] Authorization enabled
I0813 19:22:05.722856 27124 whitelist_watcher.cpp:79] No whitelist given
I0813 19:22:05.722954 27127 hierarchical.hpp:346] Initialized hierarchical allocator process
I0813 19:22:05.723054 27123 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 687204ns
I0813 19:22:05.723083 27123 replica.cpp:323] Persisted replica status to VOTING
I0813 19:22:05.723203 27115 recover.cpp:580] Successfully joined the Paxos group
I0813 19:22:05.723399 27115 recover.cpp:464] Recover process terminated
I0813 19:22:05.724145 27113 master.cpp:1524] The newly elected leader is master@172.17.2.67:42492 with id 20150813-192205-1124209068-42492-27093
I0813 19:22:05.724175 27113 master.cpp:1537] Elected as the leading master!
I0813 19:22:05.724194 27113 master.cpp:1307] Recovering from registrar
I0813 19:22:05.724302 27125 registrar.cpp:311] Recovering registrar
I0813 19:22:05.724985 27113 log.cpp:661] Attempting to start the writer
I0813 19:22:05.726019 27119 replica.cpp:477] Replica received implicit promise request with proposal 1
I0813 19:22:05.726444 27119 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 400214ns
I0813 19:22:05.726465 27119 replica.cpp:345] Persisted promised to 1
I0813 19:22:05.727037 27113 coordinator.cpp:231] Coordinator attemping to fill missing position
I0813 19:22:05.728118 27122 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0813 19:22:05.728552 27122 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 397149ns
I0813 19:22:05.728574 27122 replica.cpp:679] Persisted action at 0
I0813 19:22:05.729423 27121 replica.cpp:511] Replica received write request for position 0
I0813 19:22:05.729480 27121 leveldb.cpp:438] Reading position from leveldb took 29496ns
I0813 19:22:05.729915 27121 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 387522ns
I0813 19:22:05.729943 27121 replica.cpp:679] Persisted action at 0
I0813 19:22:05.730587 27126 replica.cpp:658] Replica received learned notice for position 0
I0813 19:22:05.731009 27126 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 397189ns
I0813 19:22:05.731039 27126 replica.cpp:679] Persisted action at 0
I0813 19:22:05.731065 27126 replica.cpp:664] Replica learned NOP action at position 0
I0813 19:22:05.731801 27127 log.cpp:677] Writer started with ending position 0
I0813 19:22:05.732760 27118 leveldb.cpp:438] Reading position from leveldb took 25934ns
I0813 19:22:05.735185 27126 registrar.cpp:344] Successfully fetched the registry (0B) in 10.727936ms
I0813 19:22:05.735299 27126 registrar.cpp:443] Applied 1 operations in 24246ns; attempting to update the 'registry'
I0813 19:22:05.735558 27112 slave.cpp:1209] Will retry registration in 57.499739ms if necessary
I0813 19:22:05.735592 27117 master.cpp:1134] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
I0813 19:22:05.737717 27120 log.cpp:685] Attempting to append 176 bytes to the log
I0813 19:22:05.737861 27117 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I0813 19:22:05.738514 27117 replica.cpp:511] Replica received write request for position 1
I0813 19:22:05.739022 27117 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 473475ns
I0813 19:22:05.739045 27117 replica.cpp:679] Persisted action at 1
I0813 19:22:05.739620 27126 replica.cpp:658] Replica received learned notice for position 1
I0813 19:22:05.740139 27126 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 492546ns
I0813 19:22:05.740164 27126 replica.cpp:679] Persisted action at 1
I0813 19:22:05.740186 27126 replica.cpp:664] Replica learned APPEND action at position 1
I0813 19:22:05.741085 27118 registrar.cpp:488] Successfully updated the 'registry' in 5.60512ms
I0813 19:22:05.741226 27118 registrar.cpp:374] Successfully recovered registrar
I0813 19:22:05.741297 27112 log.cpp:704] Attempting to truncate the log to 1
I0813 19:22:05.741423 27121 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I0813 19:22:05.741556 27120 master.cpp:1334] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I0813 19:22:05.742372 27113 replica.cpp:511] Replica received write request for position 2
I0813 19:22:05.742811 27113 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 407495ns
I0813 19:22:05.742851 27113 replica.cpp:679] Persisted action at 2
I0813 19:22:05.743538 27119 replica.cpp:658] Replica received learned notice for position 2
I0813 19:22:05.744060 27119 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 429375ns
I0813 19:22:05.744123 27119 leveldb.cpp:401] Deleting ~1 keys from leveldb took 38852ns
I0813 19:22:05.744149 27119 replica.cpp:679] Persisted action at 2
I0813 19:22:05.744169 27119 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0813 19:22:05.758908 27112 slave.cpp:190] Slave started on 212)@172.17.2.67:42492
I0813 19:22:05.758952 27112 slave.cpp:191] Flags at startup: --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/SchedulerTest_ReconcileTask_3YIfU8/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SchedulerTest_ReconcileTask_3YIfU8/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.24.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/SchedulerTest_ReconcileTask_3YIfU8"
I0813 19:22:05.759438 27112 credentials.hpp:85] Loading credential for authentication from '/tmp/SchedulerTest_ReconcileTask_3YIfU8/credential'
I0813 19:22:05.759695 27112 slave.cpp:321] Slave using credential for: test-principal
I0813 19:22:05.760205 27112 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0813 19:22:05.760301 27112 slave.cpp:384] Slave hostname: e0a808ab0d7c
I0813 19:22:05.760316 27112 slave.cpp:389] Slave checkpoint: true
I0813 19:22:05.760443 27093 scheduler.cpp:157] Version: 0.24.0
I0813 19:22:05.761139 27116 state.cpp:54] Recovering state from '/tmp/SchedulerTest_ReconcileTask_3YIfU8/meta'
I0813 19:22:05.761458 27114 status_update_manager.cpp:202] Recovering status update manager
I0813 19:22:05.761755 27115 slave.cpp:4069] Finished recovery
I0813 19:22:05.762210 27115 slave.cpp:4226] Querying resource estimator for oversubscribable resources
I0813 19:22:05.762507 27117 status_update_manager.cpp:176] Pausing sending status updates
I0813 19:22:05.762509 27115 slave.cpp:684] New master detected at master@172.17.2.67:42492
I0813 19:22:05.762622 27120 scheduler.cpp:272] New master detected at master@172.17.2.67:42492
I0813 19:22:05.762709 27115 slave.cpp:747] Authenticating with master master@172.17.2.67:42492
I0813 19:22:05.762744 27115 slave.cpp:752] Using default CRAM-MD5 authenticatee
I0813 19:22:05.762913 27115 slave.cpp:720] Detecting new master
I0813 19:22:05.763061 27119 authenticatee.cpp:115] Creating new client SASL connection
I0813 19:22:05.763080 27115 slave.cpp:4240] Received oversubscribable resources  from the resource estimator
I0813 19:22:05.763329 27115 master.cpp:4693] Authenticating slave(212)@172.17.2.67:42492
I0813 19:22:05.763715 27122 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(515)@172.17.2.67:42492
I0813 19:22:05.764057 27114 authenticator.cpp:92] Creating new server SASL connection
I0813 19:22:05.764283 27112 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I0813 19:22:05.764367 27112 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 19:22:05.764884 27117 authenticator.cpp:197] Received SASL authentication start
I0813 19:22:05.764945 27117 authenticator.cpp:319] Authentication requires more steps
I0813 19:22:05.765094 27117 authenticatee.cpp:252] Received SASL authentication step
I0813 19:22:05.765182 27117 authenticator.cpp:225] Received SASL authentication step
I0813 19:22:05.765208 27117 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'e0a808ab0d7c' server FQDN: 'e0a808ab0d7c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 19:22:05.765220 27117 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0813 19:22:05.765262 27117 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 19:22:05.765286 27117 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'e0a808ab0d7c' server FQDN: 'e0a808ab0d7c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 19:22:05.765297 27117 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 19:22:05.765306 27117 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 19:22:05.765324 27117 authenticator.cpp:311] Authentication success
I0813 19:22:05.765527 27117 authenticatee.cpp:292] Authentication success
I0813 19:22:05.765604 27117 master.cpp:4723] Successfully authenticated principal 'test-principal' at slave(212)@172.17.2.67:42492
I0813 19:22:05.765686 27117 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(515)@172.17.2.67:42492
I0813 19:22:05.765959 27126 slave.cpp:815] Successfully authenticated with master master@172.17.2.67:42492
I0813 19:22:05.766077 27126 slave.cpp:1209] Will retry registration in 13.972017ms if necessary
I0813 19:22:05.766290 27126 master.cpp:3635] Registering slave at slave(212)@172.17.2.67:42492 (e0a808ab0d7c) with id 20150813-192205-1124209068-42492-27093-S0
I0813 19:22:05.766760 27126 registrar.cpp:443] Applied 1 operations in 58762ns; attempting to update the 'registry'
I0813 19:22:05.767613 27112 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0813 19:22:05.768867 27112 master.cpp:1782] Received subscription request for HTTP framework 'default'
I0813 19:22:05.768932 27112 master.cpp:1563] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0813 19:22:05.769172 27119 master.cpp:1874] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I0813 19:22:05.769793 27119 hierarchical.hpp:391] Added framework 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.769845 27119 hierarchical.hpp:1008] No resources available to allocate!
I0813 19:22:05.769863 27119 hierarchical.hpp:908] Performed allocation for 0 slaves in 47524ns
I0813 19:22:05.770354 27119 master.hpp:1305] Sending heartbeat to 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.771143 27123 log.cpp:685] Attempting to append 347 bytes to the log
I0813 19:22:05.771368 27119 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
I0813 19:22:05.772090 27117 replica.cpp:511] Replica received write request for position 3
../../src/tests/scheduler_tests.cpp:337: Failure
Value of: event.get().type()
  Actual: HEARTBEAT
Expected: Event::OFFERS
Which is: OFFERS
I0813 19:22:05.772804 27117 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 676014ns
../../src/tests/scheduler_tests.cpp:338: Failure
Expected: (0) != (event.get().offers().offers().size()), actual: 0 vs 0
I0813 19:22:05.772860 27117 replica.cpp:679] Persisted action at 3
[libprotobuf FATAL ../3rdparty/libprocess/3rdparty/protobuf-2.5.0/src/google/protobuf/repeated_field.h:824] CHECK failed: (index) < (size()): 
../../src/tests/scheduler_tests.cpp:343: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/scheduler_tests.cpp:340: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
unknown file: Failure
C++ exception with description "CHECK failed: (index) < (size()): " thrown in the test body.
I0813 19:22:05.774121 27121 replica.cpp:658] Replica received learned notice for position 3
I0813 19:22:05.774587 27119 master.cpp:859] Master terminating
I0813 19:22:05.774618 27121 leveldb.cpp:343] Persisting action (368 bytes) to leveldb took 468721ns
I0813 19:22:05.774642 27121 replica.cpp:679] Persisted action at 3
I0813 19:22:05.774665 27121 replica.cpp:664] Replica learned APPEND action at position 3
I0813 19:22:05.774735 27112 hierarchical.hpp:428] Removed framework 20150813-192205-1124209068-42492-27093-0000
I0813 19:22:05.775338 27124 slave.cpp:3143] master@172.17.2.67:42492 exited
W0813 19:22:05.775619 27124 slave.cpp:3146] Master disconnected! Waiting for a new master to be elected
I0813 19:22:05.776721 27116 registrar.cpp:488] Successfully updated the 'registry' in 9.892864ms
I0813 19:22:05.777062 27116 log.cpp:704] Attempting to truncate the log to 3
I0813 19:22:05.777223 27121 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
I0813 19:22:05.778187 27127 replica.cpp:511] Replica received write request for position 4
I0813 19:22:05.778663 27127 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 441360ns
I0813 19:22:05.778805 27127 replica.cpp:679] Persisted action at 4
*** Aborted at 1439493725 (unix time) try "date -d @1439493725" if you are using GNU date ***
I0813 19:22:05.780897 27126 slave.cpp:1209] Will retry registration in 29.306991ms if necessary
PC: @        0x14a487bfc (unknown)
make[4]: *** [check-local] Segmentation fault
make[4]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.24.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1439492263-14872
Untagged: mesos-1439492263-14872:latest
Deleted: 840dddef832b8572c6449e8fbb3f0466b8525b12dc21aa67046d93a5936a8340
Deleted: aa2845ad0a6b6f35603be4be41665ea8fdb83a3047c0873b5e37e9f2d5f743fe
Deleted: 809151d3816a4476d36a87d4d63e184537b3f3755d937c3b0cf52f3f32936490
Deleted: 2de9d837c90a26423797eaa929c72b2b32c71e8db7e9579a9211f42a196ff81c
Deleted: 9fddb65c4ec40038b88b4bdbbbbe6ac35266117b768ee56eaea5d4a936b643c8
Deleted: bbc509d8ede724c7748c7f801ac579662172a1ba0f563f13085519655a039563
Deleted: efaeb7fdab1bb5b05dda6c4f481f2c2d3091081bc05a8b7ff5e202ff831dbfa8
Deleted: bd017c46f81702b94706d59ccce76f38d2b07d04d620f67323c13053b89f545f
Deleted: 676c6c99b5a3a8c273c8fb70ad7c0e1d968dc7fd9e6bf4d3fd7d6be379a1b84a
Deleted: 8c52ef8fb4d33d379fc3b1d688ee731fd47a1c4f9a6b32cc3ed35b82c8a6426a
Deleted: d85f8193f5231f02425625638df736ccfc807da9912071e1ebc3b2bd2157397d
Deleted: 3093ae47259f7d3306d75195965e9553f62e4d5e51fe61a16be80d854fd117bc
Build step 'Execute shell' marked build as failure

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #703

Posted by Benjamin Mahler <bm...@twitter.com.INVALID>.

We'll need to pipeline on a single connection to ensure ordering.
Alternatively, we could wait for a response before sending the next request
on a different connection, but throughput would be much lower.

On Thu, Aug 13, 2015 at 11:06 AM, Vinod Kone <vi...@apache.org> wrote:

> hmmm. this looks like decline call was received by master after revive call, even though the test sent them in the reverse order! are we violating ordered delivery?
>
>
>
> I0813 17:58:50.866607 27126 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I0813 17:58:50.866894 27126 master.cpp:3159] Processing REVIVE call for framework 20150813-175850-1375736236-37185-27097-0000 (default)
> I0813 17:58:50.867028 27118 hierarchical.hpp:884] Removed filters for framework 20150813-175850-1375736236-37185-27097-0000
> I0813 17:58:50.867162 27126 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I0813 17:58:50.867485 27118 hierarchical.hpp:1008] No resources available to allocate!
> I0813 17:58:50.867522 27118 hierarchical.hpp:908] Performed allocation for 1 slaves in 462068ns
> I0813 17:58:50.867560 27126 master.cpp:3109] Processing DECLINE call for offers: [ 20150813-175850-1375736236-37185-27097-O0 ] for framework 20150813-175850-1375736236-37185-27097-0000 (default)
> I0813 17:58:50.868141 27131 hierarchical.hpp:814] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150813-175850-1375736236-37185-27097-S0 from framework 20150813-175850-1375736236-37185-27097-0000
> I0813 17:58:50.868206 27131 hierarchical.hpp:851] Framework 20150813-175850-1375736236-37185-27097-0000 filtered slave 20150813-175850-1375736236-37185-27097-S0 for 1hrs
> 2015-08-13 17:58:51,886:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2015-08-13 17:58:55,222:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2015-08-13 17:58:58,559:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2015-08-13 17:59:01,896:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2015-08-13 17:59:05,232:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> ../../src/tests/scheduler_tests.cpp:911: Failure
> Failed to wait 15secs for event
>
>
>
>
>
>
> On Thu, Aug 13, 2015 at 11:00 AM, Apache Jenkins Server <
> jenkins@builds.apache.org> wrote:
>
>> See <
>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/703/changes
>> >
>>
>> Changes:
>>
>> [vinodkone] Exposed environment variables LIBPROCESS_ADVERTISE_IP and
>>
>> [vinodkone] Added 2 master flags --advertise_ip and --advertise_port.
>>
>> ------------------------------------------
>> [...truncated 118138 lines...]
>> I0813 18:00:59.829804 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 158ns
>> I0813 18:00:59.829835 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.830921 27125 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 612354ns
>> I0813 18:00:59.830955 27125 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.834482 27097 leveldb.cpp:176] Opened db in 2.897487ms
>> I0813 18:00:59.837293 27097 leveldb.cpp:183] Compacted db in 2.770934ms
>> I0813 18:00:59.837371 27097 leveldb.cpp:198] Created db iterator in
>> 19939ns
>> I0813 18:00:59.837410 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 20807ns
>> I0813 18:00:59.837446 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 21322ns
>> I0813 18:00:59.837483 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.840483 27097 leveldb.cpp:176] Opened db in 2.839851ms
>> I0813 18:00:59.843341 27097 leveldb.cpp:183] Compacted db in 2.794442ms
>> I0813 18:00:59.843400 27097 leveldb.cpp:198] Created db iterator in
>> 18987ns
>> I0813 18:00:59.843436 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 19902ns
>> I0813 18:00:59.843473 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 21512ns
>> I0813 18:00:59.843509 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.843986 27131 recover.cpp:449] Starting replica recovery
>> I0813 18:00:59.844211 27131 recover.cpp:475] Replica is in VOTING status
>> I0813 18:00:59.844570 27131 recover.cpp:464] Recover process terminated
>> I0813 18:00:59.847435 27126 registrar.cpp:311] Recovering registrar
>> [       OK ] Strict/RegistrarTest.FetchTimeout/0 (52 ms)
>> [ RUN      ] Strict/RegistrarTest.FetchTimeout/1
>> Using temporary directory
>> '/tmp/Strict_RegistrarTest_FetchTimeout_1_uhIU1m'
>> I0813 18:00:59.876332 27097 leveldb.cpp:176] Opened db in 3.213648ms
>> I0813 18:00:59.877480 27097 leveldb.cpp:183] Compacted db in 1.109003ms
>> I0813 18:00:59.877535 27097 leveldb.cpp:198] Created db iterator in
>> 14100ns
>> I0813 18:00:59.877555 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1785ns
>> I0813 18:00:59.877567 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 170ns
>> I0813 18:00:59.877598 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.878993 27130 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 847789ns
>> I0813 18:00:59.879030 27130 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.882300 27097 leveldb.cpp:176] Opened db in 2.715285ms
>> I0813 18:00:59.883430 27097 leveldb.cpp:183] Compacted db in 1.061899ms
>> I0813 18:00:59.883486 27097 leveldb.cpp:198] Created db iterator in
>> 13812ns
>> I0813 18:00:59.883505 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1525ns
>> I0813 18:00:59.883515 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 175ns
>> I0813 18:00:59.883546 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.885128 27119 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 599317ns
>> I0813 18:00:59.885241 27119 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.888790 27097 leveldb.cpp:176] Opened db in 2.958281ms
>> I0813 18:00:59.891683 27097 leveldb.cpp:183] Compacted db in 2.852636ms
>> I0813 18:00:59.891744 27097 leveldb.cpp:198] Created db iterator in
>> 19209ns
>> I0813 18:00:59.891783 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 19022ns
>> I0813 18:00:59.891839 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 32202ns
>> I0813 18:00:59.891901 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.895509 27097 leveldb.cpp:176] Opened db in 3.404201ms
>> I0813 18:00:59.898675 27097 leveldb.cpp:183] Compacted db in 3.127029ms
>> I0813 18:00:59.898736 27097 leveldb.cpp:198] Created db iterator in
>> 18152ns
>> I0813 18:00:59.898775 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 19404ns
>> I0813 18:00:59.898829 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 29147ns
>> I0813 18:00:59.898888 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.899489 27119 recover.cpp:449] Starting replica recovery
>> I0813 18:00:59.899799 27123 recover.cpp:475] Replica is in VOTING status
>> I0813 18:00:59.899953 27123 recover.cpp:464] Recover process terminated
>> I0813 18:00:59.902916 27120 registrar.cpp:311] Recovering registrar
>> [       OK ] Strict/RegistrarTest.FetchTimeout/1 (55 ms)
>> [ RUN      ] Strict/RegistrarTest.StoreTimeout/0
>> Using temporary directory
>> '/tmp/Strict_RegistrarTest_StoreTimeout_0_LjnuX4'
>> I0813 18:00:59.931071 27097 leveldb.cpp:176] Opened db in 3.042176ms
>> I0813 18:00:59.931990 27097 leveldb.cpp:183] Compacted db in 879281ns
>> I0813 18:00:59.932034 27097 leveldb.cpp:198] Created db iterator in
>> 12775ns
>> I0813 18:00:59.932049 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1383ns
>> I0813 18:00:59.932060 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 277ns
>> I0813 18:00:59.932091 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.932960 27131 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 423312ns
>> I0813 18:00:59.932991 27131 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.936257 27097 leveldb.cpp:176] Opened db in 2.649587ms
>> I0813 18:00:59.937361 27097 leveldb.cpp:183] Compacted db in 1.061111ms
>> I0813 18:00:59.937417 27097 leveldb.cpp:198] Created db iterator in
>> 14110ns
>> I0813 18:00:59.937438 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1755ns
>> I0813 18:00:59.937448 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 165ns
>> I0813 18:00:59.937489 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.938429 27126 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 458223ns
>> I0813 18:00:59.938460 27126 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.941510 27097 leveldb.cpp:176] Opened db in 2.492396ms
>> I0813 18:00:59.944128 27097 leveldb.cpp:183] Compacted db in 2.577304ms
>> I0813 18:00:59.944187 27097 leveldb.cpp:198] Created db iterator in
>> 17925ns
>> I0813 18:00:59.944226 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 18482ns
>> I0813 18:00:59.944268 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 25917ns
>> I0813 18:00:59.944344 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.947232 27097 leveldb.cpp:176] Opened db in 2.695198ms
>> I0813 18:00:59.950215 27097 leveldb.cpp:183] Compacted db in 2.943043ms
>> I0813 18:00:59.950278 27097 leveldb.cpp:198] Created db iterator in
>> 18937ns
>> I0813 18:00:59.950343 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 45121ns
>> I0813 18:00:59.950387 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 23904ns
>> I0813 18:00:59.950425 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.950899 27124 recover.cpp:449] Starting replica recovery
>> I0813 18:00:59.951285 27122 recover.cpp:475] Replica is in VOTING status
>> I0813 18:00:59.951458 27122 recover.cpp:464] Recover process terminated
>> I0813 18:00:59.953532 27124 registrar.cpp:311] Recovering registrar
>> I0813 18:00:59.956615 27124 registrar.cpp:344] Successfully fetched the
>> registry (0B) in 0ns
>> I0813 18:00:59.956722 27124 registrar.cpp:443] Applied 1 operations in
>> 23814ns; attempting to update the 'registry'
>> E0813 18:00:59.964251 27118 registrar.cpp:510] Registrar aborting: Failed
>> to update 'registry': Failed to perform store within 10secs
>> [       OK ] Strict/RegistrarTest.StoreTimeout/0 (51 ms)
>> [ RUN      ] Strict/RegistrarTest.StoreTimeout/1
>> Using temporary directory
>> '/tmp/Strict_RegistrarTest_StoreTimeout_1_qGnk1M'
>> I0813 18:00:59.981770 27097 leveldb.cpp:176] Opened db in 2.847776ms
>> I0813 18:00:59.982787 27097 leveldb.cpp:183] Compacted db in 980419ns
>> I0813 18:00:59.982836 27097 leveldb.cpp:198] Created db iterator in
>> 13655ns
>> I0813 18:00:59.982861 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1695ns
>> I0813 18:00:59.982872 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 182ns
>> I0813 18:00:59.982904 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.983865 27118 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 688534ns
>> I0813 18:00:59.983903 27118 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.987309 27097 leveldb.cpp:176] Opened db in 2.712145ms
>> I0813 18:00:59.988404 27097 leveldb.cpp:183] Compacted db in 1.037609ms
>> I0813 18:00:59.988459 27097 leveldb.cpp:198] Created db iterator in
>> 14020ns
>> I0813 18:00:59.988483 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1773ns
>> I0813 18:00:59.988494 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 165ns
>> I0813 18:00:59.988525 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.989332 27121 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 533023ns
>> I0813 18:00:59.989363 27121 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:00:59.992429 27097 leveldb.cpp:176] Opened db in 2.545834ms
>> I0813 18:00:59.995609 27097 leveldb.cpp:183] Compacted db in 3.138141ms
>> I0813 18:00:59.995671 27097 leveldb.cpp:198] Created db iterator in
>> 18942ns
>> I0813 18:00:59.995709 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 18967ns
>> I0813 18:00:59.995745 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 20904ns
>> I0813 18:00:59.995784 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:00:59.999143 27097 leveldb.cpp:176] Opened db in 3.165713ms
>> I0813 18:01:00.002497 27097 leveldb.cpp:183] Compacted db in 3.313371ms
>> I0813 18:01:00.002562 27097 leveldb.cpp:198] Created db iterator in
>> 19452ns
>> I0813 18:01:00.002600 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 19097ns
>> I0813 18:01:00.002637 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 22334ns
>> I0813 18:01:00.002676 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.003209 27117 recover.cpp:449] Starting replica recovery
>> I0813 18:01:00.003422 27117 recover.cpp:475] Replica is in VOTING status
>> I0813 18:01:00.003566 27117 recover.cpp:464] Recover process terminated
>> I0813 18:01:00.006894 27119 registrar.cpp:311] Recovering registrar
>> I0813 18:01:00.009877 27119 registrar.cpp:344] Successfully fetched the
>> registry (0B) in 0ns
>> I0813 18:01:00.009985 27119 registrar.cpp:443] Applied 1 operations in
>> 21921ns; attempting to update the 'registry'
>> E0813 18:01:00.017173 27125 registrar.cpp:510] Registrar aborting: Failed
>> to update 'registry': Failed to perform store within 10secs
>> [       OK ] Strict/RegistrarTest.StoreTimeout/1 (52 ms)
>> [ RUN      ] Strict/RegistrarTest.Abort/0
>> Using temporary directory '/tmp/Strict_RegistrarTest_Abort_0_nukMdv'
>> I0813 18:01:00.035025 27097 leveldb.cpp:176] Opened db in 3.062886ms
>> I0813 18:01:00.036001 27097 leveldb.cpp:183] Compacted db in 937322ns
>> I0813 18:01:00.036049 27097 leveldb.cpp:198] Created db iterator in
>> 13764ns
>> I0813 18:01:00.036070 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1667ns
>> I0813 18:01:00.036082 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 185ns
>> I0813 18:01:00.036113 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.037346 27118 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 716920ns
>> I0813 18:01:00.037384 27118 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:01:00.041075 27097 leveldb.cpp:176] Opened db in 2.98693ms
>> I0813 18:01:00.042054 27097 leveldb.cpp:183] Compacted db in 940172ns
>> I0813 18:01:00.042104 27097 leveldb.cpp:198] Created db iterator in
>> 14807ns
>> I0813 18:01:00.042124 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1495ns
>> I0813 18:01:00.042135 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 160ns
>> I0813 18:01:00.042167 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.043505 27123 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 646763ns
>> I0813 18:01:00.043542 27123 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:01:00.047478 27097 leveldb.cpp:176] Opened db in 3.410889ms
>> I0813 18:01:00.050539 27097 leveldb.cpp:183] Compacted db in 3.019957ms
>> I0813 18:01:00.050601 27097 leveldb.cpp:198] Created db iterator in
>> 19282ns
>> I0813 18:01:00.050639 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 20242ns
>> I0813 18:01:00.050675 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 21717ns
>> I0813 18:01:00.050711 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.053953 27097 leveldb.cpp:176] Opened db in 3.060909ms
>> I0813 18:01:00.056818 27097 leveldb.cpp:183] Compacted db in 2.822982ms
>> I0813 18:01:00.056877 27097 leveldb.cpp:198] Created db iterator in
>> 19217ns
>> I0813 18:01:00.056915 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 19340ns
>> I0813 18:01:00.056951 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 20672ns
>> I0813 18:01:00.056988 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.057494 27127 recover.cpp:449] Starting replica recovery
>> I0813 18:01:00.057737 27127 recover.cpp:475] Replica is in VOTING status
>> I0813 18:01:00.057899 27127 recover.cpp:464] Recover process terminated
>> I0813 18:01:00.060782 27119 registrar.cpp:311] Recovering registrar
>> I0813 18:01:00.064206 27119 registrar.cpp:344] Successfully fetched the
>> registry (0B) in 3.372032ms
>> I0813 18:01:00.064327 27119 registrar.cpp:443] Applied 1 operations in
>> 21549ns; attempting to update the 'registry'
>> I0813 18:01:00.067538 27119 registrar.cpp:488] Successfully updated the
>> 'registry' in 3.14496ms
>> I0813 18:01:00.067694 27119 registrar.cpp:374] Successfully recovered
>> registrar
>> I0813 18:01:00.068501 27119 registrar.cpp:443] Applied 1 operations in
>> 39479ns; attempting to update the 'registry'
>> E0813 18:01:00.071552 27119 registrar.cpp:510] Registrar aborting: Failed
>> to update 'registry': failure
>> [       OK ] Strict/RegistrarTest.Abort/0 (45 ms)
>> [ RUN      ] Strict/RegistrarTest.Abort/1
>> Using temporary directory '/tmp/Strict_RegistrarTest_Abort_1_m3Lpxd'
>> I0813 18:01:00.079236 27097 leveldb.cpp:176] Opened db in 3.069713ms
>> I0813 18:01:00.080219 27097 leveldb.cpp:183] Compacted db in 945064ns
>> I0813 18:01:00.080266 27097 leveldb.cpp:198] Created db iterator in
>> 13329ns
>> I0813 18:01:00.080281 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1525ns
>> I0813 18:01:00.080292 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 162ns
>> I0813 18:01:00.080343 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.081343 27120 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 541853ns
>> I0813 18:01:00.081377 27120 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:01:00.084305 27097 leveldb.cpp:176] Opened db in 2.416643ms
>> I0813 18:01:00.085175 27097 leveldb.cpp:183] Compacted db in 805604ns
>> I0813 18:01:00.085232 27097 leveldb.cpp:198] Created db iterator in
>> 15763ns
>> I0813 18:01:00.085258 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 1865ns
>> I0813 18:01:00.085276 27097 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 290ns
>> I0813 18:01:00.085345 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.086402 27118 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 503157ns
>> I0813 18:01:00.086436 27118 replica.cpp:323] Persisted replica status to
>> VOTING
>> I0813 18:01:00.089941 27097 leveldb.cpp:176] Opened db in 2.856357ms
>> I0813 18:01:00.093217 27097 leveldb.cpp:183] Compacted db in 3.233141ms
>> I0813 18:01:00.093291 27097 leveldb.cpp:198] Created db iterator in
>> 22502ns
>> I0813 18:01:00.093394 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 82563ns
>> I0813 18:01:00.093447 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 30930ns
>> I0813 18:01:00.093490 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.096662 27097 leveldb.cpp:176] Opened db in 2.990233ms
>> I0813 18:01:00.099722 27097 leveldb.cpp:183] Compacted db in 3.019507ms
>> I0813 18:01:00.099782 27097 leveldb.cpp:198] Created db iterator in
>> 19264ns
>> I0813 18:01:00.099820 27097 leveldb.cpp:204] Seeked to beginning of db in
>> 20004ns
>> I0813 18:01:00.099856 27097 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 20949ns
>> I0813 18:01:00.099894 27097 replica.cpp:744] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0813 18:01:00.100404 27121 recover.cpp:449] Starting replica recovery
>> I0813 18:01:00.100639 27121 recover.cpp:475] Replica is in VOTING status
>> I0813 18:01:00.100790 27121 recover.cpp:464] Recover process terminated
>> I0813 18:01:00.103438 27119 registrar.cpp:311] Recovering registrar
>> I0813 18:01:00.106487 27119 registrar.cpp:344] Successfully fetched the
>> registry (0B) in 2.872064ms
>> I0813 18:01:00.106591 27119 registrar.cpp:443] Applied 1 operations in
>> 19735ns; attempting to update the 'registry'
>> I0813 18:01:00.110139 27119 registrar.cpp:488] Successfully updated the
>> 'registry' in 3.47904ms
>> I0813 18:01:00.110265 27119 registrar.cpp:374] Successfully recovered
>> registrar
>> I0813 18:01:00.111085 27121 registrar.cpp:443] Applied 1 operations in
>> 50891ns; attempting to update the 'registry'
>> E0813 18:01:00.113780 27121 registrar.cpp:510] Registrar aborting: Failed
>> to update 'registry': failure
>> [       OK ] Strict/RegistrarTest.Abort/1 (42 ms)
>> [----------] 16 tests from Strict/RegistrarTest (1131 ms total)
>>
>> [----------] Global test environment tear-down
>> [==========] 704 tests from 99 test cases ran. (297709 ms total)
>> [  PASSED  ] 703 tests.
>> [  FAILED  ] 1 test, listed below:
>> [  FAILED  ] SchedulerTest.Revive
>>
>>  1 FAILED TEST
>>   YOU HAVE 8 DISABLED TESTS
>>
>> make[4]: *** [check-local] Error 1
>> make[4]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
>> make[3]: *** [check-am] Error 2
>> make[3]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
>> make[2]: *** [check] Error 2
>> make[2]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
>> make[1]: *** [check-recursive] Error 1
>> make[1]: Leaving directory `/mesos/mesos-0.24.0/_build'
>> make: *** [distcheck] Error 1
>> + docker rmi mesos-1439487492-16422
>> Untagged: mesos-1439487492-16422:latest
>> Deleted: a541dee3305bf5ca8abfab48750013174bb5ce57f1a71ded080bbc808b1a6777
>> Deleted: b044def6014d6734e18dbd4664ebd5ee39f39da422bf08db9fbed5ae69aa0eff
>> Deleted: eab26368a8b243a04b5f8bf9b3f7486cdc438320fcd1ff4a27000db4927ede19
>> Deleted: 806eed38ec2ef8864060e0af572f834442752c5bb182d3a5e9a3b37443434f24
>> Deleted: 8ac0cadfea08395a852d195317df1155a3fbd8e6d4c43067e5563fc25edf1c5d
>> Deleted: 0e3923b664dcb97eedf711ba01c77c7d998de2f02b2587ad9e4f7765f594a062
>> Deleted: 7ac414c13f03ecd0b0cc3c73678c99f8eabb28f792ab4701c58bbefe2f15aa4a
>> Deleted: c3b98cf2df0fa07fd79c17717f8ddabcc061e9a6c7264de368c885785546fd7e
>> Deleted: 0a101a1afa15d79ce6b09a40315f0ef695492b3139906f0d4409e38e4079241c
>> Deleted: c60bebff644b31001040360c88d44a1f8e78c8999d24b036f5144e090db9af5f
>> Deleted: 035ad706f75e0a788134ea4964254245d219e39b381724dd5e437edd4ff6acc5
>> Deleted: 7257527774b5114c595b294e104a23b827a322c14e989b9ebd47054f22f1aaa3
>> Build step 'Execute shell' marked build as failure
>>
>
>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent,ubuntu:14.04,docker||Hadoop #703

Posted by Vinod Kone <vi...@apache.org>.

hmmm. this looks like decline call was received by master after revive
call, even though the test sent them in the reverse order! are we
violating ordered delivery?



I0813 17:58:50.866607 27126 process.cpp:3043] Handling HTTP event for
process 'master' with path: '/master/api/v1/scheduler'
I0813 17:58:50.866894 27126 master.cpp:3159] Processing REVIVE call
for framework 20150813-175850-1375736236-37185-27097-0000 (default)
I0813 17:58:50.867028 27118 hierarchical.hpp:884] Removed filters for
framework 20150813-175850-1375736236-37185-27097-0000
I0813 17:58:50.867162 27126 process.cpp:3043] Handling HTTP event for
process 'master' with path: '/master/api/v1/scheduler'
I0813 17:58:50.867485 27118 hierarchical.hpp:1008] No resources
available to allocate!
I0813 17:58:50.867522 27118 hierarchical.hpp:908] Performed allocation
for 1 slaves in 462068ns
I0813 17:58:50.867560 27126 master.cpp:3109] Processing DECLINE call
for offers: [ 20150813-175850-1375736236-37185-27097-O0 ] for
framework 20150813-175850-1375736236-37185-27097-0000 (default)
I0813 17:58:50.868141 27131 hierarchical.hpp:814] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on
slave 20150813-175850-1375736236-37185-27097-S0 from framework
20150813-175850-1375736236-37185-27097-0000
I0813 17:58:50.868206 27131 hierarchical.hpp:851] Framework
20150813-175850-1375736236-37185-27097-0000 filtered slave
20150813-175850-1375736236-37185-27097-S0 for 1hrs
2015-08-13 17:58:51,886:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused):
server refused to accept the client
2015-08-13 17:58:55,222:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused):
server refused to accept the client
2015-08-13 17:58:58,559:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused):
server refused to accept the client
2015-08-13 17:59:01,896:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused):
server refused to accept the client
2015-08-13 17:59:05,232:27097(0x2b45cba0e700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:40177] zk retcode=-4, errno=111(Connection refused):
server refused to accept the client
../../src/tests/scheduler_tests.cpp:911: Failure
Failed to wait 15secs for event






On Thu, Aug 13, 2015 at 11:00 AM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:

> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/703/changes
> >
>
> Changes:
>
> [vinodkone] Exposed environment variables LIBPROCESS_ADVERTISE_IP and
>
> [vinodkone] Added 2 master flags --advertise_ip and --advertise_port.
>
> ------------------------------------------
> [...truncated 118138 lines...]
> I0813 18:00:59.829804 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 158ns
> I0813 18:00:59.829835 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.830921 27125 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 612354ns
> I0813 18:00:59.830955 27125 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.834482 27097 leveldb.cpp:176] Opened db in 2.897487ms
> I0813 18:00:59.837293 27097 leveldb.cpp:183] Compacted db in 2.770934ms
> I0813 18:00:59.837371 27097 leveldb.cpp:198] Created db iterator in 19939ns
> I0813 18:00:59.837410 27097 leveldb.cpp:204] Seeked to beginning of db in
> 20807ns
> I0813 18:00:59.837446 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 21322ns
> I0813 18:00:59.837483 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.840483 27097 leveldb.cpp:176] Opened db in 2.839851ms
> I0813 18:00:59.843341 27097 leveldb.cpp:183] Compacted db in 2.794442ms
> I0813 18:00:59.843400 27097 leveldb.cpp:198] Created db iterator in 18987ns
> I0813 18:00:59.843436 27097 leveldb.cpp:204] Seeked to beginning of db in
> 19902ns
> I0813 18:00:59.843473 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 21512ns
> I0813 18:00:59.843509 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.843986 27131 recover.cpp:449] Starting replica recovery
> I0813 18:00:59.844211 27131 recover.cpp:475] Replica is in VOTING status
> I0813 18:00:59.844570 27131 recover.cpp:464] Recover process terminated
> I0813 18:00:59.847435 27126 registrar.cpp:311] Recovering registrar
> [       OK ] Strict/RegistrarTest.FetchTimeout/0 (52 ms)
> [ RUN      ] Strict/RegistrarTest.FetchTimeout/1
> Using temporary directory '/tmp/Strict_RegistrarTest_FetchTimeout_1_uhIU1m'
> I0813 18:00:59.876332 27097 leveldb.cpp:176] Opened db in 3.213648ms
> I0813 18:00:59.877480 27097 leveldb.cpp:183] Compacted db in 1.109003ms
> I0813 18:00:59.877535 27097 leveldb.cpp:198] Created db iterator in 14100ns
> I0813 18:00:59.877555 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1785ns
> I0813 18:00:59.877567 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 170ns
> I0813 18:00:59.877598 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.878993 27130 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 847789ns
> I0813 18:00:59.879030 27130 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.882300 27097 leveldb.cpp:176] Opened db in 2.715285ms
> I0813 18:00:59.883430 27097 leveldb.cpp:183] Compacted db in 1.061899ms
> I0813 18:00:59.883486 27097 leveldb.cpp:198] Created db iterator in 13812ns
> I0813 18:00:59.883505 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1525ns
> I0813 18:00:59.883515 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 175ns
> I0813 18:00:59.883546 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.885128 27119 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 599317ns
> I0813 18:00:59.885241 27119 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.888790 27097 leveldb.cpp:176] Opened db in 2.958281ms
> I0813 18:00:59.891683 27097 leveldb.cpp:183] Compacted db in 2.852636ms
> I0813 18:00:59.891744 27097 leveldb.cpp:198] Created db iterator in 19209ns
> I0813 18:00:59.891783 27097 leveldb.cpp:204] Seeked to beginning of db in
> 19022ns
> I0813 18:00:59.891839 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 32202ns
> I0813 18:00:59.891901 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.895509 27097 leveldb.cpp:176] Opened db in 3.404201ms
> I0813 18:00:59.898675 27097 leveldb.cpp:183] Compacted db in 3.127029ms
> I0813 18:00:59.898736 27097 leveldb.cpp:198] Created db iterator in 18152ns
> I0813 18:00:59.898775 27097 leveldb.cpp:204] Seeked to beginning of db in
> 19404ns
> I0813 18:00:59.898829 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 29147ns
> I0813 18:00:59.898888 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.899489 27119 recover.cpp:449] Starting replica recovery
> I0813 18:00:59.899799 27123 recover.cpp:475] Replica is in VOTING status
> I0813 18:00:59.899953 27123 recover.cpp:464] Recover process terminated
> I0813 18:00:59.902916 27120 registrar.cpp:311] Recovering registrar
> [       OK ] Strict/RegistrarTest.FetchTimeout/1 (55 ms)
> [ RUN      ] Strict/RegistrarTest.StoreTimeout/0
> Using temporary directory '/tmp/Strict_RegistrarTest_StoreTimeout_0_LjnuX4'
> I0813 18:00:59.931071 27097 leveldb.cpp:176] Opened db in 3.042176ms
> I0813 18:00:59.931990 27097 leveldb.cpp:183] Compacted db in 879281ns
> I0813 18:00:59.932034 27097 leveldb.cpp:198] Created db iterator in 12775ns
> I0813 18:00:59.932049 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1383ns
> I0813 18:00:59.932060 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 277ns
> I0813 18:00:59.932091 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.932960 27131 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 423312ns
> I0813 18:00:59.932991 27131 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.936257 27097 leveldb.cpp:176] Opened db in 2.649587ms
> I0813 18:00:59.937361 27097 leveldb.cpp:183] Compacted db in 1.061111ms
> I0813 18:00:59.937417 27097 leveldb.cpp:198] Created db iterator in 14110ns
> I0813 18:00:59.937438 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1755ns
> I0813 18:00:59.937448 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 165ns
> I0813 18:00:59.937489 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.938429 27126 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 458223ns
> I0813 18:00:59.938460 27126 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.941510 27097 leveldb.cpp:176] Opened db in 2.492396ms
> I0813 18:00:59.944128 27097 leveldb.cpp:183] Compacted db in 2.577304ms
> I0813 18:00:59.944187 27097 leveldb.cpp:198] Created db iterator in 17925ns
> I0813 18:00:59.944226 27097 leveldb.cpp:204] Seeked to beginning of db in
> 18482ns
> I0813 18:00:59.944268 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 25917ns
> I0813 18:00:59.944344 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.947232 27097 leveldb.cpp:176] Opened db in 2.695198ms
> I0813 18:00:59.950215 27097 leveldb.cpp:183] Compacted db in 2.943043ms
> I0813 18:00:59.950278 27097 leveldb.cpp:198] Created db iterator in 18937ns
> I0813 18:00:59.950343 27097 leveldb.cpp:204] Seeked to beginning of db in
> 45121ns
> I0813 18:00:59.950387 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 23904ns
> I0813 18:00:59.950425 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.950899 27124 recover.cpp:449] Starting replica recovery
> I0813 18:00:59.951285 27122 recover.cpp:475] Replica is in VOTING status
> I0813 18:00:59.951458 27122 recover.cpp:464] Recover process terminated
> I0813 18:00:59.953532 27124 registrar.cpp:311] Recovering registrar
> I0813 18:00:59.956615 27124 registrar.cpp:344] Successfully fetched the
> registry (0B) in 0ns
> I0813 18:00:59.956722 27124 registrar.cpp:443] Applied 1 operations in
> 23814ns; attempting to update the 'registry'
> E0813 18:00:59.964251 27118 registrar.cpp:510] Registrar aborting: Failed
> to update 'registry': Failed to perform store within 10secs
> [       OK ] Strict/RegistrarTest.StoreTimeout/0 (51 ms)
> [ RUN      ] Strict/RegistrarTest.StoreTimeout/1
> Using temporary directory '/tmp/Strict_RegistrarTest_StoreTimeout_1_qGnk1M'
> I0813 18:00:59.981770 27097 leveldb.cpp:176] Opened db in 2.847776ms
> I0813 18:00:59.982787 27097 leveldb.cpp:183] Compacted db in 980419ns
> I0813 18:00:59.982836 27097 leveldb.cpp:198] Created db iterator in 13655ns
> I0813 18:00:59.982861 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1695ns
> I0813 18:00:59.982872 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 182ns
> I0813 18:00:59.982904 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.983865 27118 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 688534ns
> I0813 18:00:59.983903 27118 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.987309 27097 leveldb.cpp:176] Opened db in 2.712145ms
> I0813 18:00:59.988404 27097 leveldb.cpp:183] Compacted db in 1.037609ms
> I0813 18:00:59.988459 27097 leveldb.cpp:198] Created db iterator in 14020ns
> I0813 18:00:59.988483 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1773ns
> I0813 18:00:59.988494 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 165ns
> I0813 18:00:59.988525 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.989332 27121 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 533023ns
> I0813 18:00:59.989363 27121 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:00:59.992429 27097 leveldb.cpp:176] Opened db in 2.545834ms
> I0813 18:00:59.995609 27097 leveldb.cpp:183] Compacted db in 3.138141ms
> I0813 18:00:59.995671 27097 leveldb.cpp:198] Created db iterator in 18942ns
> I0813 18:00:59.995709 27097 leveldb.cpp:204] Seeked to beginning of db in
> 18967ns
> I0813 18:00:59.995745 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 20904ns
> I0813 18:00:59.995784 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:00:59.999143 27097 leveldb.cpp:176] Opened db in 3.165713ms
> I0813 18:01:00.002497 27097 leveldb.cpp:183] Compacted db in 3.313371ms
> I0813 18:01:00.002562 27097 leveldb.cpp:198] Created db iterator in 19452ns
> I0813 18:01:00.002600 27097 leveldb.cpp:204] Seeked to beginning of db in
> 19097ns
> I0813 18:01:00.002637 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 22334ns
> I0813 18:01:00.002676 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.003209 27117 recover.cpp:449] Starting replica recovery
> I0813 18:01:00.003422 27117 recover.cpp:475] Replica is in VOTING status
> I0813 18:01:00.003566 27117 recover.cpp:464] Recover process terminated
> I0813 18:01:00.006894 27119 registrar.cpp:311] Recovering registrar
> I0813 18:01:00.009877 27119 registrar.cpp:344] Successfully fetched the
> registry (0B) in 0ns
> I0813 18:01:00.009985 27119 registrar.cpp:443] Applied 1 operations in
> 21921ns; attempting to update the 'registry'
> E0813 18:01:00.017173 27125 registrar.cpp:510] Registrar aborting: Failed
> to update 'registry': Failed to perform store within 10secs
> [       OK ] Strict/RegistrarTest.StoreTimeout/1 (52 ms)
> [ RUN      ] Strict/RegistrarTest.Abort/0
> Using temporary directory '/tmp/Strict_RegistrarTest_Abort_0_nukMdv'
> I0813 18:01:00.035025 27097 leveldb.cpp:176] Opened db in 3.062886ms
> I0813 18:01:00.036001 27097 leveldb.cpp:183] Compacted db in 937322ns
> I0813 18:01:00.036049 27097 leveldb.cpp:198] Created db iterator in 13764ns
> I0813 18:01:00.036070 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1667ns
> I0813 18:01:00.036082 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 185ns
> I0813 18:01:00.036113 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.037346 27118 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 716920ns
> I0813 18:01:00.037384 27118 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:01:00.041075 27097 leveldb.cpp:176] Opened db in 2.98693ms
> I0813 18:01:00.042054 27097 leveldb.cpp:183] Compacted db in 940172ns
> I0813 18:01:00.042104 27097 leveldb.cpp:198] Created db iterator in 14807ns
> I0813 18:01:00.042124 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1495ns
> I0813 18:01:00.042135 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 160ns
> I0813 18:01:00.042167 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.043505 27123 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 646763ns
> I0813 18:01:00.043542 27123 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:01:00.047478 27097 leveldb.cpp:176] Opened db in 3.410889ms
> I0813 18:01:00.050539 27097 leveldb.cpp:183] Compacted db in 3.019957ms
> I0813 18:01:00.050601 27097 leveldb.cpp:198] Created db iterator in 19282ns
> I0813 18:01:00.050639 27097 leveldb.cpp:204] Seeked to beginning of db in
> 20242ns
> I0813 18:01:00.050675 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 21717ns
> I0813 18:01:00.050711 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.053953 27097 leveldb.cpp:176] Opened db in 3.060909ms
> I0813 18:01:00.056818 27097 leveldb.cpp:183] Compacted db in 2.822982ms
> I0813 18:01:00.056877 27097 leveldb.cpp:198] Created db iterator in 19217ns
> I0813 18:01:00.056915 27097 leveldb.cpp:204] Seeked to beginning of db in
> 19340ns
> I0813 18:01:00.056951 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 20672ns
> I0813 18:01:00.056988 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.057494 27127 recover.cpp:449] Starting replica recovery
> I0813 18:01:00.057737 27127 recover.cpp:475] Replica is in VOTING status
> I0813 18:01:00.057899 27127 recover.cpp:464] Recover process terminated
> I0813 18:01:00.060782 27119 registrar.cpp:311] Recovering registrar
> I0813 18:01:00.064206 27119 registrar.cpp:344] Successfully fetched the
> registry (0B) in 3.372032ms
> I0813 18:01:00.064327 27119 registrar.cpp:443] Applied 1 operations in
> 21549ns; attempting to update the 'registry'
> I0813 18:01:00.067538 27119 registrar.cpp:488] Successfully updated the
> 'registry' in 3.14496ms
> I0813 18:01:00.067694 27119 registrar.cpp:374] Successfully recovered
> registrar
> I0813 18:01:00.068501 27119 registrar.cpp:443] Applied 1 operations in
> 39479ns; attempting to update the 'registry'
> E0813 18:01:00.071552 27119 registrar.cpp:510] Registrar aborting: Failed
> to update 'registry': failure
> [       OK ] Strict/RegistrarTest.Abort/0 (45 ms)
> [ RUN      ] Strict/RegistrarTest.Abort/1
> Using temporary directory '/tmp/Strict_RegistrarTest_Abort_1_m3Lpxd'
> I0813 18:01:00.079236 27097 leveldb.cpp:176] Opened db in 3.069713ms
> I0813 18:01:00.080219 27097 leveldb.cpp:183] Compacted db in 945064ns
> I0813 18:01:00.080266 27097 leveldb.cpp:198] Created db iterator in 13329ns
> I0813 18:01:00.080281 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1525ns
> I0813 18:01:00.080292 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 162ns
> I0813 18:01:00.080343 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.081343 27120 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 541853ns
> I0813 18:01:00.081377 27120 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:01:00.084305 27097 leveldb.cpp:176] Opened db in 2.416643ms
> I0813 18:01:00.085175 27097 leveldb.cpp:183] Compacted db in 805604ns
> I0813 18:01:00.085232 27097 leveldb.cpp:198] Created db iterator in 15763ns
> I0813 18:01:00.085258 27097 leveldb.cpp:204] Seeked to beginning of db in
> 1865ns
> I0813 18:01:00.085276 27097 leveldb.cpp:273] Iterated through 0 keys in
> the db in 290ns
> I0813 18:01:00.085345 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.086402 27118 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 503157ns
> I0813 18:01:00.086436 27118 replica.cpp:323] Persisted replica status to
> VOTING
> I0813 18:01:00.089941 27097 leveldb.cpp:176] Opened db in 2.856357ms
> I0813 18:01:00.093217 27097 leveldb.cpp:183] Compacted db in 3.233141ms
> I0813 18:01:00.093291 27097 leveldb.cpp:198] Created db iterator in 22502ns
> I0813 18:01:00.093394 27097 leveldb.cpp:204] Seeked to beginning of db in
> 82563ns
> I0813 18:01:00.093447 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 30930ns
> I0813 18:01:00.093490 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.096662 27097 leveldb.cpp:176] Opened db in 2.990233ms
> I0813 18:01:00.099722 27097 leveldb.cpp:183] Compacted db in 3.019507ms
> I0813 18:01:00.099782 27097 leveldb.cpp:198] Created db iterator in 19264ns
> I0813 18:01:00.099820 27097 leveldb.cpp:204] Seeked to beginning of db in
> 20004ns
> I0813 18:01:00.099856 27097 leveldb.cpp:273] Iterated through 1 keys in
> the db in 20949ns
> I0813 18:01:00.099894 27097 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 18:01:00.100404 27121 recover.cpp:449] Starting replica recovery
> I0813 18:01:00.100639 27121 recover.cpp:475] Replica is in VOTING status
> I0813 18:01:00.100790 27121 recover.cpp:464] Recover process terminated
> I0813 18:01:00.103438 27119 registrar.cpp:311] Recovering registrar
> I0813 18:01:00.106487 27119 registrar.cpp:344] Successfully fetched the
> registry (0B) in 2.872064ms
> I0813 18:01:00.106591 27119 registrar.cpp:443] Applied 1 operations in
> 19735ns; attempting to update the 'registry'
> I0813 18:01:00.110139 27119 registrar.cpp:488] Successfully updated the
> 'registry' in 3.47904ms
> I0813 18:01:00.110265 27119 registrar.cpp:374] Successfully recovered
> registrar
> I0813 18:01:00.111085 27121 registrar.cpp:443] Applied 1 operations in
> 50891ns; attempting to update the 'registry'
> E0813 18:01:00.113780 27121 registrar.cpp:510] Registrar aborting: Failed
> to update 'registry': failure
> [       OK ] Strict/RegistrarTest.Abort/1 (42 ms)
> [----------] 16 tests from Strict/RegistrarTest (1131 ms total)
>
> [----------] Global test environment tear-down
> [==========] 704 tests from 99 test cases ran. (297709 ms total)
> [  PASSED  ] 703 tests.
> [  FAILED  ] 1 test, listed below:
> [  FAILED  ] SchedulerTest.Revive
>
>  1 FAILED TEST
>   YOU HAVE 8 DISABLED TESTS
>
> make[4]: *** [check-local] Error 1
> make[4]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
> make[3]: *** [check-am] Error 2
> make[3]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
> make[2]: *** [check] Error 2
> make[2]: Leaving directory `/mesos/mesos-0.24.0/_build/src'
> make[1]: *** [check-recursive] Error 1
> make[1]: Leaving directory `/mesos/mesos-0.24.0/_build'
> make: *** [distcheck] Error 1
> + docker rmi mesos-1439487492-16422
> Untagged: mesos-1439487492-16422:latest
> Deleted: a541dee3305bf5ca8abfab48750013174bb5ce57f1a71ded080bbc808b1a6777
> Deleted: b044def6014d6734e18dbd4664ebd5ee39f39da422bf08db9fbed5ae69aa0eff
> Deleted: eab26368a8b243a04b5f8bf9b3f7486cdc438320fcd1ff4a27000db4927ede19
> Deleted: 806eed38ec2ef8864060e0af572f834442752c5bb182d3a5e9a3b37443434f24
> Deleted: 8ac0cadfea08395a852d195317df1155a3fbd8e6d4c43067e5563fc25edf1c5d
> Deleted: 0e3923b664dcb97eedf711ba01c77c7d998de2f02b2587ad9e4f7765f594a062
> Deleted: 7ac414c13f03ecd0b0cc3c73678c99f8eabb28f792ab4701c58bbefe2f15aa4a
> Deleted: c3b98cf2df0fa07fd79c17717f8ddabcc061e9a6c7264de368c885785546fd7e
> Deleted: 0a101a1afa15d79ce6b09a40315f0ef695492b3139906f0d4409e38e4079241c
> Deleted: c60bebff644b31001040360c88d44a1f8e78c8999d24b036f5144e090db9af5f
> Deleted: 035ad706f75e0a788134ea4964254245d219e39b381724dd5e437edd4ff6acc5
> Deleted: 7257527774b5114c595b294e104a23b827a322c14e989b9ebd47054f22f1aaa3
> Build step 'Execute shell' marked build as failure
>