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

[Apache Jenkins Server <je...@builds.apache.org>]

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

Changes:

[mpark] Introduced filter for non-revocable resources.

[mpark] Updated codebase to use `nonRevocable()` where appropriate.

------------------------------------------
[...truncated 150475 lines...]
I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default' for gc 6.9999984545837days in the future
I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000' for gc 6.99999845272days in the future
I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing status update streams for framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
[       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
[ RUN      ] ContentType/SchedulerTest.Request/0
I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in 36.820837ms
I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in 28745ns
I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db in 4075ns
I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys in the db in 506ns
I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11259)@172.17.21.0:52024
I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status to STARTING
I1201 13:13:39.310650 30317 master.cpp:365] Master afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on 172.17.21.0:52024
I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui" --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
I1201 13:13:39.311813 30317 master.cpp:414] Master allowing unauthenticated frameworks to register
I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing authenticated slaves to register
I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials for authentication from '/tmp/ZHbR13/credentials'
I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5' authenticator
I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized hierarchical allocator process
I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist given
I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 26.131683ms
I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status to STARTING
I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING status
I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader is master@172.17.21.0:52024 with id afc8b3bb-8b30-42f9-bb3d-e218e05c5758
I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading master!
I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11261)@172.17.21.0:52024
I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover response from a replica in STARTING status
I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status to VOTING
I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 19.367885ms
I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status to VOTING
I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the Paxos group
I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit promise request from (11262)@172.17.21.0:52024 with proposal 1
I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 20.816751ms
I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit promise request from (11263)@172.17.21.0:52024 for position 0 with proposal 2
I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 21.553914ms
I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write request for position 0 from (11264)@172.17.21.0:52024
I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from leveldb took 138547ns
I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 21.856586ms
I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 22.672674ms
I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP action at position 0
I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending position 0
I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from leveldb took 54316ns
I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched the registry (0B) in 135.67488ms
I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in 58207ns; attempting to update the 'registry'
I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171 bytes to the log
I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write request for position 1 from (11265)@172.17.21.0:52024
I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190 bytes) to leveldb took 24.470564ms
I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 23.909555ms
I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND action at position 1
I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated the 'registry' in 56.57088ms
I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered registrar
I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the log to 1
I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from the Registry (132B) ; allowing 10mins for slaves to re-register
I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery is not supported yet
I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write request for position 2 from (11266)@172.17.21.0:52024
I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 26.14166ms
I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 22.715014ms
I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from leveldb took 68387ns
I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at master@172.17.21.0:52024
I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.21.0:52024
I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.21.0:58671
I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation for 0 slaves in 278800ns
I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.21.0:52024
I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.21.0:52024
I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring HEARTBEAT event
I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to master@172.17.21.0:52024
I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.21.0:58672
I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call for framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
[ RUN      ] ContentType/SchedulerTest.Request/1
I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in 41.862895ms
I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in 28393ns
I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db in 3402ns
I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys in the db in 424ns
I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11270)@172.17.21.0:52024
I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status to STARTING
I1201 13:13:39.842226 30310 master.cpp:365] Master f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on 172.17.21.0:52024
I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui" --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
I1201 13:13:39.843057 30310 master.cpp:414] Master allowing unauthenticated frameworks to register
I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing authenticated slaves to register
I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials for authentication from '/tmp/BZ8798/credentials'
I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5' authenticator
I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist given
I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized hierarchical allocator process
I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader is master@172.17.21.0:52024 with id f1235cbb-2af4-4048-8379-cb927ec30140
I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading master!
I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 154.538135ms
I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status to STARTING
I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING status
I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11272)@172.17.21.0:52024
I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover response from a replica in STARTING status
I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status to VOTING
2015-12-01 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 153.522723ms
I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status to VOTING
I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the Paxos group
I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit promise request from (11273)@172.17.21.0:52024 with proposal 1
I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 30.196031ms
I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit promise request from (11274)@172.17.21.0:52024 for position 0 with proposal 2
I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 21.637902ms
I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write request for position 0 from (11275)@172.17.21.0:52024
I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from leveldb took 57423ns
I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 23.068613ms
I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 24.122945ms
I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP action at position 0
I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending position 0
I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from leveldb took 51852ns
I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched the registry (0B) in 406.404096ms
I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in 32037ns; attempting to update the 'registry'
I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171 bytes to the log
I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write request for position 1 from (11276)@172.17.21.0:52024
I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190 bytes) to leveldb took 38.855065ms
I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 28.359915ms
I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND action at position 1
I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated the 'registry' in 77.036288ms
I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered registrar
I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the log to 1
I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write request for position 2 from (11277)@172.17.21.0:52024
I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from the Registry (132B) ; allowing 10mins for slaves to re-register
I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery is not supported yet
I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 29.65284ms
I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 31.661429ms
I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from leveldb took 75229ns
I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at master@172.17.21.0:52024
I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.21.0:52024
I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.21.0:58674
I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation for 0 slaves in 88470ns
I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to f1235cbb-2af4-4048-8379-cb927ec30140-0000
I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.21.0:52024
I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.21.0:52024
I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring HEARTBEAT event
I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to master@172.17.21.0:52024
I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.21.0:58675
I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call for framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
[----------] 22 tests from ContentType/SchedulerTest (17087 ms total)

[----------] Global test environment tear-down
[==========] 860 tests from 115 test cases ran. (821953 ms total)
[  PASSED  ] 858 tests.
[  FAILED  ] 2 tests, listed below:
[  FAILED  ] HealthCheckTest.CheckCommandTimeout
[  FAILED  ] PersistentVolumeTest.SlaveRecovery

 2 FAILED TESTS
  YOU HAVE 7 DISABLED TESTS

make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1448971321-13066
Untagged: mesos-1448971321-13066:latest
Deleted: 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
Deleted: 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
Deleted: b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
Deleted: d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
Deleted: 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
Deleted: d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
Deleted: 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
Deleted: 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
Deleted: daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
Deleted: 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
Deleted: 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
Deleted: 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
Deleted: 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
Build step 'Execute shell' marked build as failure

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

[Apache Jenkins Server <je...@builds.apache.org>]

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

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

[Jie Yu <yu...@gmail.com>]

I committed a fix:

commit ec3a5423a1205053fe4ef4a44ead0ed1338169f0
Author: Jie Yu <yu...@gmail.com>
Date:   Fri Dec 4 12:26:10 2015 -0800

    Fixed the flaky PersistentVolumeTest.SlaveRecovery test.

    Review: https://reviews.apache.org/r/40985

On Fri, Dec 4, 2015 at 11:34 AM, Jie Yu <yu...@gmail.com> wrote:

> https://issues.apache.org/jira/browse/MESOS-3907
>
> On Fri, Dec 4, 2015 at 1:10 AM, Michael Park <mp...@mesosphere.io> wrote:
>
>> +Jie Yu <yu...@gmail.com> as the author of the test.
>>
>> This one looks a bit tricky to me. Will continue looking tomorrow.
>>
>> On Thu, Dec 3, 2015 at 10:50 PM Benjamin Mahler <
>> benjamin.mahler@gmail.com> wrote:
>>
>>> Thank you sir!
>>>
>>> On Thu, Dec 3, 2015 at 7:45 PM, Michael Park <mp...@mesosphere.io>
>>> wrote:
>>>
>>>> Yep, I'll look into it once I get back to a computer.
>>>>
>>>> On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <
>>>> benjamin.mahler@gmail.com> wrote:
>>>>
>>>>> Michael, this looks like
>>>>> https://issues.apache.org/jira/browse/MESOS-3907? Can you please
>>>>> triage it?
>>>>>
>>>>> Tim, I've added details to
>>>>> https://issues.apache.org/jira/browse/MESOS-4024. Can you please
>>>>> triage it? Also, the test takes 16 seconds to finish? :(
>>>>>
>>>>> On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
>>>>> jenkins@builds.apache.org> wrote:
>>>>>
>>>>>> See <
>>>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
>>>>>> >
>>>>>>
>>>>>> Changes:
>>>>>>
>>>>>> [mpark] Introduced filter for non-revocable resources.
>>>>>>
>>>>>> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>>>>>>
>>>>>> ------------------------------------------
>>>>>> [...truncated 150475 lines...]
>>>>>> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
>>>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
>>>>>> for gc 6.9999984545837days in the future
>>>>>> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
>>>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
>>>>>> for gc 6.99999845272days in the future
>>>>>> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing
>>>>>> status update streams for framework
>>>>>> 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>>>> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning
>>>>>> up status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
>>>>>> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>>>> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
>>>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>>>> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
>>>>>> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in
>>>>>> 36.820837ms
>>>>>> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in
>>>>>> 28745ns
>>>>>> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of
>>>>>> db in 4075ns
>>>>>> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys
>>>>>> in the db in 506ns
>>>>>> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with
>>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>>> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
>>>>>> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY
>>>>>> status
>>>>>> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
>>>>>> received a broadcasted recover request from (11259)@172.17.21.0:52024
>>>>>> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover
>>>>>> response from a replica in EMPTY status
>>>>>> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status
>>>>>> to STARTING
>>>>>> I1201 13:13:39.310650 30317 master.cpp:365] Master
>>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
>>>>>> 172.17.21.0:52024
>>>>>> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup:
>>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>>> --authenticators="crammd5" --authorizers="local"
>>>>>> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
>>>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>>>> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
>>>>>> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
>>>>>> unauthenticated frameworks to register
>>>>>> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
>>>>>> authenticated slaves to register
>>>>>> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials
>>>>>> for authentication from '/tmp/ZHbR13/credentials'
>>>>>> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
>>>>>> authenticator
>>>>>> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
>>>>>> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized
>>>>>> hierarchical allocator process
>>>>>> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist
>>>>>> given
>>>>>> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 26.131683ms
>>>>>> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status
>>>>>> to STARTING
>>>>>> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING
>>>>>> status
>>>>>> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader
>>>>>> is master@172.17.21.0:52024 with id
>>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758
>>>>>> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading
>>>>>> master!
>>>>>> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
>>>>>> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
>>>>>> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING
>>>>>> status received a broadcasted recover request from (11261)@
>>>>>> 172.17.21.0:52024
>>>>>> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover
>>>>>> response from a replica in STARTING status
>>>>>> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status
>>>>>> to VOTING
>>>>>> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 19.367885ms
>>>>>> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status
>>>>>> to VOTING
>>>>>> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the
>>>>>> Paxos group
>>>>>> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process
>>>>>> terminated
>>>>>> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the
>>>>>> writer
>>>>>> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received
>>>>>> implicit promise request from (11262)@172.17.21.0:52024 with
>>>>>> proposal 1
>>>>>> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 20.816751ms
>>>>>> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
>>>>>> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator
>>>>>> attempting to fill missing positions
>>>>>> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received
>>>>>> explicit promise request from (11263)@172.17.21.0:52024 for position
>>>>>> 0 with proposal 2
>>>>>> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8
>>>>>> bytes) to leveldb took 21.553914ms
>>>>>> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
>>>>>> request for position 0 from (11264)@172.17.21.0:52024
>>>>>> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 138547ns
>>>>>> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14
>>>>>> bytes) to leveldb took 21.856586ms
>>>>>> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
>>>>>> notice for position 0 from @0.0.0.0:0
>>>>>> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 22.672674ms
>>>>>> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP
>>>>>> action at position 0
>>>>>> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
>>>>>> position 0
>>>>>> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 54316ns
>>>>>> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched
>>>>>> the registry (0B) in 135.67488ms
>>>>>> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations
>>>>>> in 58207ns; attempting to update the 'registry'
>>>>>> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171
>>>>>> bytes to the log
>>>>>> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator
>>>>>> attempting to write APPEND action at position 1
>>>>>> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
>>>>>> request for position 1 from (11265)@172.17.21.0:52024
>>>>>> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190
>>>>>> bytes) to leveldb took 24.470564ms
>>>>>> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
>>>>>> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
>>>>>> notice for position 1 from @0.0.0.0:0
>>>>>> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192
>>>>>> bytes) to leveldb took 23.909555ms
>>>>>> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
>>>>>> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND
>>>>>> action at position 1
>>>>>> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated
>>>>>> the 'registry' in 56.57088ms
>>>>>> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
>>>>>> registrar
>>>>>> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the
>>>>>> log to 1
>>>>>> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from
>>>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>>>> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery
>>>>>> is not supported yet
>>>>>> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator
>>>>>> attempting to write TRUNCATE action at position 2
>>>>>> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
>>>>>> request for position 2 from (11266)@172.17.21.0:52024
>>>>>> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 26.14166ms
>>>>>> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
>>>>>> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
>>>>>> notice for position 2 from @0.0.0.0:0
>>>>>> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18
>>>>>> bytes) to leveldb took 22.715014ms
>>>>>> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from
>>>>>> leveldb took 68387ns
>>>>>> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
>>>>>> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
>>>>>> action at position 2
>>>>>> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
>>>>>> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
>>>>>> master@172.17.21.0:52024
>>>>>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>>> to master@172.17.21.0:52024
>>>>>> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.21.0:58671
>>>>>> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription
>>>>>> request for HTTP framework 'default'
>>>>>> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
>>>>>> principal 'test-principal' to receive offers for role '*'
>>>>>> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
>>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>>> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
>>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>>> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources
>>>>>> available to allocate!
>>>>>> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers
>>>>>> to send out!
>>>>>> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed
>>>>>> allocation for 0 slaves in 278800ns
>>>>>> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
>>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>>> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event
>>>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>>>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event
>>>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>>>> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172]
>>>>>> Ignoring HEARTBEAT event
>>>>>> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call
>>>>>> to master@172.17.21.0:52024
>>>>>> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.21.0:58672
>>>>>> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call
>>>>>> for framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
>>>>>> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
>>>>>> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>>> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
>>>>>> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
>>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>>> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received
>>>>>> from master. The master closed the event stream
>>>>>> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
>>>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>>>> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
>>>>>> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in
>>>>>> 41.862895ms
>>>>>> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in
>>>>>> 28393ns
>>>>>> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of
>>>>>> db in 3402ns
>>>>>> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys
>>>>>> in the db in 424ns
>>>>>> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with
>>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>>> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
>>>>>> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY
>>>>>> status
>>>>>> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
>>>>>> received a broadcasted recover request from (11270)@172.17.21.0:52024
>>>>>> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover
>>>>>> response from a replica in EMPTY status
>>>>>> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status
>>>>>> to STARTING
>>>>>> I1201 13:13:39.842226 30310 master.cpp:365] Master
>>>>>> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
>>>>>> 172.17.21.0:52024
>>>>>> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup:
>>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>>> --authenticators="crammd5" --authorizers="local"
>>>>>> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
>>>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>>>> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
>>>>>> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
>>>>>> unauthenticated frameworks to register
>>>>>> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
>>>>>> authenticated slaves to register
>>>>>> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials
>>>>>> for authentication from '/tmp/BZ8798/credentials'
>>>>>> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
>>>>>> authenticator
>>>>>> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
>>>>>> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist
>>>>>> given
>>>>>> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized
>>>>>> hierarchical allocator process
>>>>>> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader
>>>>>> is master@172.17.21.0:52024 with id
>>>>>> f1235cbb-2af4-4048-8379-cb927ec30140
>>>>>> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading
>>>>>> master!
>>>>>> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
>>>>>> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
>>>>>> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 154.538135ms
>>>>>> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status
>>>>>> to STARTING
>>>>>> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING
>>>>>> status
>>>>>> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING
>>>>>> status received a broadcasted recover request from (11272)@
>>>>>> 172.17.21.0:52024
>>>>>> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover
>>>>>> response from a replica in STARTING status
>>>>>> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status
>>>>>> to VOTING
>>>>>> 2015-12-01
>>>>>> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
>>>>>> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection
>>>>>> refused): server refused to accept the client
>>>>>> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 153.522723ms
>>>>>> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status
>>>>>> to VOTING
>>>>>> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the
>>>>>> Paxos group
>>>>>> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process
>>>>>> terminated
>>>>>> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the
>>>>>> writer
>>>>>> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received
>>>>>> implicit promise request from (11273)@172.17.21.0:52024 with
>>>>>> proposal 1
>>>>>> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 30.196031ms
>>>>>> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
>>>>>> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator
>>>>>> attempting to fill missing positions
>>>>>> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received
>>>>>> explicit promise request from (11274)@172.17.21.0:52024 for position
>>>>>> 0 with proposal 2
>>>>>> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8
>>>>>> bytes) to leveldb took 21.637902ms
>>>>>> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
>>>>>> request for position 0 from (11275)@172.17.21.0:52024
>>>>>> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 57423ns
>>>>>> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14
>>>>>> bytes) to leveldb took 23.068613ms
>>>>>> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
>>>>>> notice for position 0 from @0.0.0.0:0
>>>>>> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 24.122945ms
>>>>>> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
>>>>>> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP
>>>>>> action at position 0
>>>>>> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
>>>>>> position 0
>>>>>> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 51852ns
>>>>>> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched
>>>>>> the registry (0B) in 406.404096ms
>>>>>> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations
>>>>>> in 32037ns; attempting to update the 'registry'
>>>>>> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171
>>>>>> bytes to the log
>>>>>> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator
>>>>>> attempting to write APPEND action at position 1
>>>>>> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
>>>>>> request for position 1 from (11276)@172.17.21.0:52024
>>>>>> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190
>>>>>> bytes) to leveldb took 38.855065ms
>>>>>> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
>>>>>> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
>>>>>> notice for position 1 from @0.0.0.0:0
>>>>>> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192
>>>>>> bytes) to leveldb took 28.359915ms
>>>>>> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
>>>>>> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND
>>>>>> action at position 1
>>>>>> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated
>>>>>> the 'registry' in 77.036288ms
>>>>>> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
>>>>>> registrar
>>>>>> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the
>>>>>> log to 1
>>>>>> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator
>>>>>> attempting to write TRUNCATE action at position 2
>>>>>> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
>>>>>> request for position 2 from (11277)@172.17.21.0:52024
>>>>>> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from
>>>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>>>> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery
>>>>>> is not supported yet
>>>>>> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 29.65284ms
>>>>>> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
>>>>>> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
>>>>>> notice for position 2 from @0.0.0.0:0
>>>>>> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18
>>>>>> bytes) to leveldb took 31.661429ms
>>>>>> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from
>>>>>> leveldb took 75229ns
>>>>>> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
>>>>>> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
>>>>>> action at position 2
>>>>>> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
>>>>>> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
>>>>>> master@172.17.21.0:52024
>>>>>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>>> to master@172.17.21.0:52024
>>>>>> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.21.0:58674
>>>>>> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription
>>>>>> request for HTTP framework 'default'
>>>>>> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
>>>>>> principal 'test-principal' to receive offers for role '*'
>>>>>> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
>>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>>> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
>>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>>> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources
>>>>>> available to allocate!
>>>>>> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers
>>>>>> to send out!
>>>>>> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed
>>>>>> allocation for 0 slaves in 88470ns
>>>>>> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
>>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>>> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event
>>>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>>>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event
>>>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>>>> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172]
>>>>>> Ignoring HEARTBEAT event
>>>>>> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call
>>>>>> to master@172.17.21.0:52024
>>>>>> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.21.0:58675
>>>>>> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call
>>>>>> for framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
>>>>>> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
>>>>>> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>>> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
>>>>>> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
>>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>>> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received
>>>>>> from master. The master closed the event stream
>>>>>> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
>>>>>> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>>>>>>
>>>>>> [----------] Global test environment tear-down
>>>>>> [==========] 860 tests from 115 test cases ran. (821953 ms total)
>>>>>> [  PASSED  ] 858 tests.
>>>>>> [  FAILED  ] 2 tests, listed below:
>>>>>> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
>>>>>> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>>>>>>
>>>>>>  2 FAILED TESTS
>>>>>>   YOU HAVE 7 DISABLED TESTS
>>>>>>
>>>>>> make[4]: *** [check-local] Error 1
>>>>>> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>>> make[3]: *** [check-am] Error 2
>>>>>> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>>> make[2]: *** [check] Error 2
>>>>>> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>>> make[1]: *** [check-recursive] Error 1
>>>>>> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
>>>>>> make: *** [distcheck] Error 1
>>>>>> + docker rmi mesos-1448971321-13066
>>>>>> Untagged: mesos-1448971321-13066:latest
>>>>>> Deleted:
>>>>>> 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
>>>>>> Deleted:
>>>>>> 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
>>>>>> Deleted:
>>>>>> b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
>>>>>> Deleted:
>>>>>> d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
>>>>>> Deleted:
>>>>>> 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
>>>>>> Deleted:
>>>>>> d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
>>>>>> Deleted:
>>>>>> 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
>>>>>> Deleted:
>>>>>> 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
>>>>>> Deleted:
>>>>>> daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
>>>>>> Deleted:
>>>>>> 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
>>>>>> Deleted:
>>>>>> 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
>>>>>> Deleted:
>>>>>> 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
>>>>>> Deleted:
>>>>>> 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
>>>>>> Build step 'Execute shell' marked build as failure
>>>>>>
>>>>>
>>>>>
>>>
>

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

[Jie Yu <yu...@gmail.com>]

https://issues.apache.org/jira/browse/MESOS-3907

On Fri, Dec 4, 2015 at 1:10 AM, Michael Park <mp...@mesosphere.io> wrote:

> +Jie Yu <yu...@gmail.com> as the author of the test.
>
> This one looks a bit tricky to me. Will continue looking tomorrow.
>
> On Thu, Dec 3, 2015 at 10:50 PM Benjamin Mahler <be...@gmail.com>
> wrote:
>
>> Thank you sir!
>>
>> On Thu, Dec 3, 2015 at 7:45 PM, Michael Park <mp...@mesosphere.io> wrote:
>>
>>> Yep, I'll look into it once I get back to a computer.
>>>
>>> On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <be...@gmail.com>
>>> wrote:
>>>
>>>> Michael, this looks like
>>>> https://issues.apache.org/jira/browse/MESOS-3907? Can you please
>>>> triage it?
>>>>
>>>> Tim, I've added details to
>>>> https://issues.apache.org/jira/browse/MESOS-4024. Can you please
>>>> triage it? Also, the test takes 16 seconds to finish? :(
>>>>
>>>> On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
>>>> jenkins@builds.apache.org> wrote:
>>>>
>>>>> See <
>>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
>>>>> >
>>>>>
>>>>> Changes:
>>>>>
>>>>> [mpark] Introduced filter for non-revocable resources.
>>>>>
>>>>> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>>>>>
>>>>> ------------------------------------------
>>>>> [...truncated 150475 lines...]
>>>>> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
>>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
>>>>> for gc 6.9999984545837days in the future
>>>>> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
>>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
>>>>> for gc 6.99999845272days in the future
>>>>> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing
>>>>> status update streams for framework
>>>>> 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>>> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up
>>>>> status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
>>>>> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>>> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
>>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>>> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
>>>>> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in
>>>>> 36.820837ms
>>>>> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in
>>>>> 28745ns
>>>>> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db
>>>>> in 4075ns
>>>>> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys
>>>>> in the db in 506ns
>>>>> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with
>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
>>>>> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
>>>>> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
>>>>> received a broadcasted recover request from (11259)@172.17.21.0:52024
>>>>> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover
>>>>> response from a replica in EMPTY status
>>>>> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status
>>>>> to STARTING
>>>>> I1201 13:13:39.310650 30317 master.cpp:365] Master
>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
>>>>> 172.17.21.0:52024
>>>>> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup:
>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>> --authenticators="crammd5" --authorizers="local"
>>>>> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
>>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>>> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
>>>>> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
>>>>> unauthenticated frameworks to register
>>>>> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
>>>>> authenticated slaves to register
>>>>> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials
>>>>> for authentication from '/tmp/ZHbR13/credentials'
>>>>> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
>>>>> authenticator
>>>>> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
>>>>> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized
>>>>> hierarchical allocator process
>>>>> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist
>>>>> given
>>>>> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 26.131683ms
>>>>> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status
>>>>> to STARTING
>>>>> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING
>>>>> status
>>>>> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader
>>>>> is master@172.17.21.0:52024 with id
>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758
>>>>> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading
>>>>> master!
>>>>> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
>>>>> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
>>>>> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING
>>>>> status received a broadcasted recover request from (11261)@
>>>>> 172.17.21.0:52024
>>>>> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover
>>>>> response from a replica in STARTING status
>>>>> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status
>>>>> to VOTING
>>>>> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 19.367885ms
>>>>> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status
>>>>> to VOTING
>>>>> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the
>>>>> Paxos group
>>>>> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
>>>>> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
>>>>> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit
>>>>> promise request from (11262)@172.17.21.0:52024 with proposal 1
>>>>> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 20.816751ms
>>>>> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
>>>>> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator
>>>>> attempting to fill missing positions
>>>>> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit
>>>>> promise request from (11263)@172.17.21.0:52024 for position 0 with
>>>>> proposal 2
>>>>> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8
>>>>> bytes) to leveldb took 21.553914ms
>>>>> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
>>>>> request for position 0 from (11264)@172.17.21.0:52024
>>>>> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from
>>>>> leveldb took 138547ns
>>>>> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14
>>>>> bytes) to leveldb took 21.856586ms
>>>>> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
>>>>> notice for position 0 from @0.0.0.0:0
>>>>> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 22.672674ms
>>>>> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP
>>>>> action at position 0
>>>>> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
>>>>> position 0
>>>>> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from
>>>>> leveldb took 54316ns
>>>>> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched
>>>>> the registry (0B) in 135.67488ms
>>>>> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in
>>>>> 58207ns; attempting to update the 'registry'
>>>>> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171
>>>>> bytes to the log
>>>>> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator
>>>>> attempting to write APPEND action at position 1
>>>>> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
>>>>> request for position 1 from (11265)@172.17.21.0:52024
>>>>> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190
>>>>> bytes) to leveldb took 24.470564ms
>>>>> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
>>>>> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
>>>>> notice for position 1 from @0.0.0.0:0
>>>>> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192
>>>>> bytes) to leveldb took 23.909555ms
>>>>> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
>>>>> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND
>>>>> action at position 1
>>>>> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated
>>>>> the 'registry' in 56.57088ms
>>>>> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
>>>>> registrar
>>>>> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the
>>>>> log to 1
>>>>> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from
>>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>>> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery
>>>>> is not supported yet
>>>>> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator
>>>>> attempting to write TRUNCATE action at position 2
>>>>> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
>>>>> request for position 2 from (11266)@172.17.21.0:52024
>>>>> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 26.14166ms
>>>>> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
>>>>> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
>>>>> notice for position 2 from @0.0.0.0:0
>>>>> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18
>>>>> bytes) to leveldb took 22.715014ms
>>>>> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from
>>>>> leveldb took 68387ns
>>>>> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
>>>>> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
>>>>> action at position 2
>>>>> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
>>>>> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
>>>>> master@172.17.21.0:52024
>>>>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>> to master@172.17.21.0:52024
>>>>> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.21.0:58671
>>>>> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription
>>>>> request for HTTP framework 'default'
>>>>> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
>>>>> principal 'test-principal' to receive offers for role '*'
>>>>> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources
>>>>> available to allocate!
>>>>> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers
>>>>> to send out!
>>>>> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation
>>>>> for 0 slaves in 278800ns
>>>>> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event
>>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event
>>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>>> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring
>>>>> HEARTBEAT event
>>>>> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to
>>>>> master@172.17.21.0:52024
>>>>> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.21.0:58672
>>>>> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call
>>>>> for framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
>>>>> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
>>>>> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
>>>>> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
>>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>>> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received
>>>>> from master. The master closed the event stream
>>>>> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
>>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>>> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
>>>>> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in
>>>>> 41.862895ms
>>>>> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in
>>>>> 28393ns
>>>>> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db
>>>>> in 3402ns
>>>>> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys
>>>>> in the db in 424ns
>>>>> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with
>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
>>>>> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
>>>>> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
>>>>> received a broadcasted recover request from (11270)@172.17.21.0:52024
>>>>> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover
>>>>> response from a replica in EMPTY status
>>>>> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status
>>>>> to STARTING
>>>>> I1201 13:13:39.842226 30310 master.cpp:365] Master
>>>>> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
>>>>> 172.17.21.0:52024
>>>>> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup:
>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>> --authenticators="crammd5" --authorizers="local"
>>>>> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
>>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>>> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
>>>>> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
>>>>> unauthenticated frameworks to register
>>>>> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
>>>>> authenticated slaves to register
>>>>> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials
>>>>> for authentication from '/tmp/BZ8798/credentials'
>>>>> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
>>>>> authenticator
>>>>> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
>>>>> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist
>>>>> given
>>>>> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized
>>>>> hierarchical allocator process
>>>>> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader
>>>>> is master@172.17.21.0:52024 with id
>>>>> f1235cbb-2af4-4048-8379-cb927ec30140
>>>>> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading
>>>>> master!
>>>>> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
>>>>> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
>>>>> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 154.538135ms
>>>>> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status
>>>>> to STARTING
>>>>> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING
>>>>> status
>>>>> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING
>>>>> status received a broadcasted recover request from (11272)@
>>>>> 172.17.21.0:52024
>>>>> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover
>>>>> response from a replica in STARTING status
>>>>> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status
>>>>> to VOTING
>>>>> 2015-12-01
>>>>> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
>>>>> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection
>>>>> refused): server refused to accept the client
>>>>> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 153.522723ms
>>>>> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status
>>>>> to VOTING
>>>>> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the
>>>>> Paxos group
>>>>> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
>>>>> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
>>>>> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit
>>>>> promise request from (11273)@172.17.21.0:52024 with proposal 1
>>>>> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 30.196031ms
>>>>> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
>>>>> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator
>>>>> attempting to fill missing positions
>>>>> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit
>>>>> promise request from (11274)@172.17.21.0:52024 for position 0 with
>>>>> proposal 2
>>>>> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8
>>>>> bytes) to leveldb took 21.637902ms
>>>>> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
>>>>> request for position 0 from (11275)@172.17.21.0:52024
>>>>> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from
>>>>> leveldb took 57423ns
>>>>> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14
>>>>> bytes) to leveldb took 23.068613ms
>>>>> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
>>>>> notice for position 0 from @0.0.0.0:0
>>>>> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 24.122945ms
>>>>> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
>>>>> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP
>>>>> action at position 0
>>>>> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
>>>>> position 0
>>>>> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from
>>>>> leveldb took 51852ns
>>>>> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched
>>>>> the registry (0B) in 406.404096ms
>>>>> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in
>>>>> 32037ns; attempting to update the 'registry'
>>>>> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171
>>>>> bytes to the log
>>>>> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator
>>>>> attempting to write APPEND action at position 1
>>>>> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
>>>>> request for position 1 from (11276)@172.17.21.0:52024
>>>>> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190
>>>>> bytes) to leveldb took 38.855065ms
>>>>> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
>>>>> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
>>>>> notice for position 1 from @0.0.0.0:0
>>>>> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192
>>>>> bytes) to leveldb took 28.359915ms
>>>>> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
>>>>> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND
>>>>> action at position 1
>>>>> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated
>>>>> the 'registry' in 77.036288ms
>>>>> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
>>>>> registrar
>>>>> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the
>>>>> log to 1
>>>>> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator
>>>>> attempting to write TRUNCATE action at position 2
>>>>> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
>>>>> request for position 2 from (11277)@172.17.21.0:52024
>>>>> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from
>>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>>> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery
>>>>> is not supported yet
>>>>> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 29.65284ms
>>>>> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
>>>>> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
>>>>> notice for position 2 from @0.0.0.0:0
>>>>> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18
>>>>> bytes) to leveldb took 31.661429ms
>>>>> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from
>>>>> leveldb took 75229ns
>>>>> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
>>>>> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
>>>>> action at position 2
>>>>> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
>>>>> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
>>>>> master@172.17.21.0:52024
>>>>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>> to master@172.17.21.0:52024
>>>>> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.21.0:58674
>>>>> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription
>>>>> request for HTTP framework 'default'
>>>>> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
>>>>> principal 'test-principal' to receive offers for role '*'
>>>>> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources
>>>>> available to allocate!
>>>>> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers
>>>>> to send out!
>>>>> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation
>>>>> for 0 slaves in 88470ns
>>>>> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event
>>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event
>>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>>> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring
>>>>> HEARTBEAT event
>>>>> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to
>>>>> master@172.17.21.0:52024
>>>>> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.21.0:58675
>>>>> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call
>>>>> for framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
>>>>> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
>>>>> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
>>>>> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
>>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>>> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received
>>>>> from master. The master closed the event stream
>>>>> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
>>>>> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>>>>>
>>>>> [----------] Global test environment tear-down
>>>>> [==========] 860 tests from 115 test cases ran. (821953 ms total)
>>>>> [  PASSED  ] 858 tests.
>>>>> [  FAILED  ] 2 tests, listed below:
>>>>> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
>>>>> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>>>>>
>>>>>  2 FAILED TESTS
>>>>>   YOU HAVE 7 DISABLED TESTS
>>>>>
>>>>> make[4]: *** [check-local] Error 1
>>>>> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>> make[3]: *** [check-am] Error 2
>>>>> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>> make[2]: *** [check] Error 2
>>>>> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>>> make[1]: *** [check-recursive] Error 1
>>>>> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
>>>>> make: *** [distcheck] Error 1
>>>>> + docker rmi mesos-1448971321-13066
>>>>> Untagged: mesos-1448971321-13066:latest
>>>>> Deleted:
>>>>> 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
>>>>> Deleted:
>>>>> 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
>>>>> Deleted:
>>>>> b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
>>>>> Deleted:
>>>>> d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
>>>>> Deleted:
>>>>> 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
>>>>> Deleted:
>>>>> d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
>>>>> Deleted:
>>>>> 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
>>>>> Deleted:
>>>>> 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
>>>>> Deleted:
>>>>> daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
>>>>> Deleted:
>>>>> 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
>>>>> Deleted:
>>>>> 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
>>>>> Deleted:
>>>>> 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
>>>>> Deleted:
>>>>> 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
>>>>> Build step 'Execute shell' marked build as failure
>>>>>
>>>>
>>>>
>>

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

[Michael Park <mp...@mesosphere.io>]

+Jie Yu <yu...@gmail.com> as the author of the test.

This one looks a bit tricky to me. Will continue looking tomorrow.

On Thu, Dec 3, 2015 at 10:50 PM Benjamin Mahler <be...@gmail.com>
wrote:

> Thank you sir!
>
> On Thu, Dec 3, 2015 at 7:45 PM, Michael Park <mp...@mesosphere.io> wrote:
>
>> Yep, I'll look into it once I get back to a computer.
>>
>> On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <be...@gmail.com>
>> wrote:
>>
>>> Michael, this looks like
>>> https://issues.apache.org/jira/browse/MESOS-3907? Can you please triage
>>> it?
>>>
>>> Tim, I've added details to
>>> https://issues.apache.org/jira/browse/MESOS-4024. Can you please triage
>>> it? Also, the test takes 16 seconds to finish? :(
>>>
>>> On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
>>> jenkins@builds.apache.org> wrote:
>>>
>>>> See <
>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
>>>> >
>>>>
>>>> Changes:
>>>>
>>>> [mpark] Introduced filter for non-revocable resources.
>>>>
>>>> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>>>>
>>>> ------------------------------------------
>>>> [...truncated 150475 lines...]
>>>> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
>>>> for gc 6.9999984545837days in the future
>>>> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
>>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
>>>> for gc 6.99999845272days in the future
>>>> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing
>>>> status update streams for framework
>>>> 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up
>>>> status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
>>>> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>>> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
>>>> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in 36.820837ms
>>>> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in
>>>> 28745ns
>>>> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db
>>>> in 4075ns
>>>> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys in
>>>> the db in 506ns
>>>> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with log
>>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>>> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
>>>> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
>>>> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
>>>> received a broadcasted recover request from (11259)@172.17.21.0:52024
>>>> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover
>>>> response from a replica in EMPTY status
>>>> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status to
>>>> STARTING
>>>> I1201 13:13:39.310650 30317 master.cpp:365] Master
>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
>>>> 172.17.21.0:52024
>>>> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup: --acls=""
>>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>> --authenticate="false" --authenticate_slaves="true"
>>>> --authenticators="crammd5" --authorizers="local"
>>>> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
>>>> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
>>>> unauthenticated frameworks to register
>>>> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
>>>> authenticated slaves to register
>>>> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials for
>>>> authentication from '/tmp/ZHbR13/credentials'
>>>> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
>>>> authenticator
>>>> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
>>>> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized
>>>> hierarchical allocator process
>>>> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist given
>>>> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 26.131683ms
>>>> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status
>>>> to STARTING
>>>> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING
>>>> status
>>>> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader
>>>> is master@172.17.21.0:52024 with id
>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758
>>>> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading
>>>> master!
>>>> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
>>>> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
>>>> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING status
>>>> received a broadcasted recover request from (11261)@172.17.21.0:52024
>>>> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover
>>>> response from a replica in STARTING status
>>>> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status to
>>>> VOTING
>>>> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 19.367885ms
>>>> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status
>>>> to VOTING
>>>> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the
>>>> Paxos group
>>>> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
>>>> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
>>>> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit
>>>> promise request from (11262)@172.17.21.0:52024 with proposal 1
>>>> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 20.816751ms
>>>> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
>>>> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator attempting
>>>> to fill missing positions
>>>> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit
>>>> promise request from (11263)@172.17.21.0:52024 for position 0 with
>>>> proposal 2
>>>> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8
>>>> bytes) to leveldb took 21.553914ms
>>>> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
>>>> request for position 0 from (11264)@172.17.21.0:52024
>>>> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from
>>>> leveldb took 138547ns
>>>> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14
>>>> bytes) to leveldb took 21.856586ms
>>>> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
>>>> notice for position 0 from @0.0.0.0:0
>>>> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 22.672674ms
>>>> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP action
>>>> at position 0
>>>> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
>>>> position 0
>>>> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from
>>>> leveldb took 54316ns
>>>> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched the
>>>> registry (0B) in 135.67488ms
>>>> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in
>>>> 58207ns; attempting to update the 'registry'
>>>> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171 bytes
>>>> to the log
>>>> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator attempting
>>>> to write APPEND action at position 1
>>>> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
>>>> request for position 1 from (11265)@172.17.21.0:52024
>>>> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190
>>>> bytes) to leveldb took 24.470564ms
>>>> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
>>>> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
>>>> notice for position 1 from @0.0.0.0:0
>>>> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192
>>>> bytes) to leveldb took 23.909555ms
>>>> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
>>>> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND
>>>> action at position 1
>>>> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated the
>>>> 'registry' in 56.57088ms
>>>> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
>>>> registrar
>>>> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the log
>>>> to 1
>>>> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from
>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery is
>>>> not supported yet
>>>> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator attempting
>>>> to write TRUNCATE action at position 2
>>>> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
>>>> request for position 2 from (11266)@172.17.21.0:52024
>>>> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 26.14166ms
>>>> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
>>>> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
>>>> notice for position 2 from @0.0.0.0:0
>>>> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18
>>>> bytes) to leveldb took 22.715014ms
>>>> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from
>>>> leveldb took 68387ns
>>>> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
>>>> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
>>>> action at position 2
>>>> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
>>>> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
>>>> master@172.17.21.0:52024
>>>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call
>>>> to master@172.17.21.0:52024
>>>> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.21.0:58671
>>>> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription
>>>> request for HTTP framework 'default'
>>>> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
>>>> principal 'test-principal' to receive offers for role '*'
>>>> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources
>>>> available to allocate!
>>>> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers to
>>>> send out!
>>>> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation
>>>> for 0 slaves in 278800ns
>>>> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event
>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event
>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring
>>>> HEARTBEAT event
>>>> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to
>>>> master@172.17.21.0:52024
>>>> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.21.0:58672
>>>> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call
>>>> for framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
>>>> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
>>>> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
>>>> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
>>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>>> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received
>>>> from master. The master closed the event stream
>>>> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
>>>> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in 41.862895ms
>>>> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in
>>>> 28393ns
>>>> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db
>>>> in 3402ns
>>>> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys in
>>>> the db in 424ns
>>>> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with log
>>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>>> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
>>>> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
>>>> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
>>>> received a broadcasted recover request from (11270)@172.17.21.0:52024
>>>> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover
>>>> response from a replica in EMPTY status
>>>> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status to
>>>> STARTING
>>>> I1201 13:13:39.842226 30310 master.cpp:365] Master
>>>> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
>>>> 172.17.21.0:52024
>>>> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup: --acls=""
>>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>> --authenticate="false" --authenticate_slaves="true"
>>>> --authenticators="crammd5" --authorizers="local"
>>>> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
>>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>>> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
>>>> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
>>>> unauthenticated frameworks to register
>>>> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
>>>> authenticated slaves to register
>>>> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials for
>>>> authentication from '/tmp/BZ8798/credentials'
>>>> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
>>>> authenticator
>>>> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
>>>> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist given
>>>> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized
>>>> hierarchical allocator process
>>>> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader
>>>> is master@172.17.21.0:52024 with id
>>>> f1235cbb-2af4-4048-8379-cb927ec30140
>>>> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading
>>>> master!
>>>> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
>>>> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
>>>> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 154.538135ms
>>>> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status
>>>> to STARTING
>>>> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING
>>>> status
>>>> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING status
>>>> received a broadcasted recover request from (11272)@172.17.21.0:52024
>>>> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover
>>>> response from a replica in STARTING status
>>>> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status to
>>>> VOTING
>>>> 2015-12-01
>>>> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
>>>> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection refused):
>>>> server refused to accept the client
>>>> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 153.522723ms
>>>> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status
>>>> to VOTING
>>>> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the
>>>> Paxos group
>>>> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
>>>> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
>>>> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit
>>>> promise request from (11273)@172.17.21.0:52024 with proposal 1
>>>> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 30.196031ms
>>>> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
>>>> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator attempting
>>>> to fill missing positions
>>>> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit
>>>> promise request from (11274)@172.17.21.0:52024 for position 0 with
>>>> proposal 2
>>>> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8
>>>> bytes) to leveldb took 21.637902ms
>>>> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
>>>> request for position 0 from (11275)@172.17.21.0:52024
>>>> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from
>>>> leveldb took 57423ns
>>>> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14
>>>> bytes) to leveldb took 23.068613ms
>>>> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
>>>> notice for position 0 from @0.0.0.0:0
>>>> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 24.122945ms
>>>> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
>>>> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP action
>>>> at position 0
>>>> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
>>>> position 0
>>>> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from
>>>> leveldb took 51852ns
>>>> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched the
>>>> registry (0B) in 406.404096ms
>>>> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in
>>>> 32037ns; attempting to update the 'registry'
>>>> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171 bytes
>>>> to the log
>>>> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator attempting
>>>> to write APPEND action at position 1
>>>> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
>>>> request for position 1 from (11276)@172.17.21.0:52024
>>>> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190
>>>> bytes) to leveldb took 38.855065ms
>>>> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
>>>> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
>>>> notice for position 1 from @0.0.0.0:0
>>>> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192
>>>> bytes) to leveldb took 28.359915ms
>>>> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
>>>> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND
>>>> action at position 1
>>>> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated the
>>>> 'registry' in 77.036288ms
>>>> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
>>>> registrar
>>>> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the log
>>>> to 1
>>>> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator attempting
>>>> to write TRUNCATE action at position 2
>>>> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
>>>> request for position 2 from (11277)@172.17.21.0:52024
>>>> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from
>>>> the Registry (132B) ; allowing 10mins for slaves to re-register
>>>> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery is
>>>> not supported yet
>>>> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 29.65284ms
>>>> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
>>>> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
>>>> notice for position 2 from @0.0.0.0:0
>>>> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18
>>>> bytes) to leveldb took 31.661429ms
>>>> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from
>>>> leveldb took 75229ns
>>>> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
>>>> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
>>>> action at position 2
>>>> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
>>>> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
>>>> master@172.17.21.0:52024
>>>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call
>>>> to master@172.17.21.0:52024
>>>> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.21.0:58674
>>>> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription
>>>> request for HTTP framework 'default'
>>>> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
>>>> principal 'test-principal' to receive offers for role '*'
>>>> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources
>>>> available to allocate!
>>>> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers to
>>>> send out!
>>>> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation
>>>> for 0 slaves in 88470ns
>>>> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event
>>>> SUBSCRIBED received from master@172.17.21.0:52024
>>>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event
>>>> HEARTBEAT received from master@172.17.21.0:52024
>>>> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring
>>>> HEARTBEAT event
>>>> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to
>>>> master@172.17.21.0:52024
>>>> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.21.0:58675
>>>> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call
>>>> for framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
>>>> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
>>>> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
>>>> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
>>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>>> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received
>>>> from master. The master closed the event stream
>>>> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
>>>> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>>>>
>>>> [----------] Global test environment tear-down
>>>> [==========] 860 tests from 115 test cases ran. (821953 ms total)
>>>> [  PASSED  ] 858 tests.
>>>> [  FAILED  ] 2 tests, listed below:
>>>> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
>>>> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>>>>
>>>>  2 FAILED TESTS
>>>>   YOU HAVE 7 DISABLED TESTS
>>>>
>>>> make[4]: *** [check-local] Error 1
>>>> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>> make[3]: *** [check-am] Error 2
>>>> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>> make[2]: *** [check] Error 2
>>>> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>>> make[1]: *** [check-recursive] Error 1
>>>> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
>>>> make: *** [distcheck] Error 1
>>>> + docker rmi mesos-1448971321-13066
>>>> Untagged: mesos-1448971321-13066:latest
>>>> Deleted:
>>>> 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
>>>> Deleted:
>>>> 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
>>>> Deleted:
>>>> b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
>>>> Deleted:
>>>> d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
>>>> Deleted:
>>>> 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
>>>> Deleted:
>>>> d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
>>>> Deleted:
>>>> 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
>>>> Deleted:
>>>> 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
>>>> Deleted:
>>>> daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
>>>> Deleted:
>>>> 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
>>>> Deleted:
>>>> 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
>>>> Deleted:
>>>> 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
>>>> Deleted:
>>>> 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
>>>> Build step 'Execute shell' marked build as failure
>>>>
>>>
>>>
>

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

[Benjamin Mahler <be...@gmail.com>]

Thank you sir!

On Thu, Dec 3, 2015 at 7:45 PM, Michael Park <mp...@mesosphere.io> wrote:

> Yep, I'll look into it once I get back to a computer.
>
> On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <be...@gmail.com>
> wrote:
>
>> Michael, this looks like https://issues.apache.org/jira/browse/MESOS-3907?
>> Can you please triage it?
>>
>> Tim, I've added details to
>> https://issues.apache.org/jira/browse/MESOS-4024. Can you please triage
>> it? Also, the test takes 16 seconds to finish? :(
>>
>> On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
>> jenkins@builds.apache.org> wrote:
>>
>>> See <
>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
>>> >
>>>
>>> Changes:
>>>
>>> [mpark] Introduced filter for non-revocable resources.
>>>
>>> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>>>
>>> ------------------------------------------
>>> [...truncated 150475 lines...]
>>> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
>>> for gc 6.9999984545837days in the future
>>> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
>>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
>>> for gc 6.99999845272days in the future
>>> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing
>>> status update streams for framework
>>> 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up
>>> status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
>>> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>>> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
>>> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in 36.820837ms
>>> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in
>>> 28745ns
>>> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db
>>> in 4075ns
>>> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys in
>>> the db in 506ns
>>> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with log
>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
>>> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
>>> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
>>> received a broadcasted recover request from (11259)@172.17.21.0:52024
>>> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover response
>>> from a replica in EMPTY status
>>> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status to
>>> STARTING
>>> I1201 13:13:39.310650 30317 master.cpp:365] Master
>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
>>> 172.17.21.0:52024
>>> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup: --acls=""
>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>> --authenticate="false" --authenticate_slaves="true"
>>> --authenticators="crammd5" --authorizers="local"
>>> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
>>> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
>>> unauthenticated frameworks to register
>>> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
>>> authenticated slaves to register
>>> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials for
>>> authentication from '/tmp/ZHbR13/credentials'
>>> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
>>> authenticator
>>> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
>>> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized
>>> hierarchical allocator process
>>> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist given
>>> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 26.131683ms
>>> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status to
>>> STARTING
>>> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING
>>> status
>>> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader is
>>> master@172.17.21.0:52024 with id afc8b3bb-8b30-42f9-bb3d-e218e05c5758
>>> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading
>>> master!
>>> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
>>> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
>>> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING status
>>> received a broadcasted recover request from (11261)@172.17.21.0:52024
>>> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover response
>>> from a replica in STARTING status
>>> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status to
>>> VOTING
>>> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 19.367885ms
>>> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status to
>>> VOTING
>>> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the
>>> Paxos group
>>> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
>>> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
>>> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit
>>> promise request from (11262)@172.17.21.0:52024 with proposal 1
>>> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 20.816751ms
>>> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
>>> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator attempting
>>> to fill missing positions
>>> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit
>>> promise request from (11263)@172.17.21.0:52024 for position 0 with
>>> proposal 2
>>> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8 bytes)
>>> to leveldb took 21.553914ms
>>> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
>>> request for position 0 from (11264)@172.17.21.0:52024
>>> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from
>>> leveldb took 138547ns
>>> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14
>>> bytes) to leveldb took 21.856586ms
>>> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
>>> notice for position 0 from @0.0.0.0:0
>>> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 22.672674ms
>>> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP action
>>> at position 0
>>> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
>>> position 0
>>> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from
>>> leveldb took 54316ns
>>> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched the
>>> registry (0B) in 135.67488ms
>>> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in
>>> 58207ns; attempting to update the 'registry'
>>> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171 bytes
>>> to the log
>>> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator attempting
>>> to write APPEND action at position 1
>>> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
>>> request for position 1 from (11265)@172.17.21.0:52024
>>> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190
>>> bytes) to leveldb took 24.470564ms
>>> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
>>> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
>>> notice for position 1 from @0.0.0.0:0
>>> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192
>>> bytes) to leveldb took 23.909555ms
>>> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
>>> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND
>>> action at position 1
>>> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated the
>>> 'registry' in 56.57088ms
>>> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
>>> registrar
>>> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the log
>>> to 1
>>> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from the
>>> Registry (132B) ; allowing 10mins for slaves to re-register
>>> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery is
>>> not supported yet
>>> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator attempting
>>> to write TRUNCATE action at position 2
>>> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
>>> request for position 2 from (11266)@172.17.21.0:52024
>>> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 26.14166ms
>>> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
>>> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
>>> notice for position 2 from @0.0.0.0:0
>>> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18
>>> bytes) to leveldb took 22.715014ms
>>> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from
>>> leveldb took 68387ns
>>> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
>>> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
>>> action at position 2
>>> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
>>> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
>>> master@172.17.21.0:52024
>>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call to
>>> master@172.17.21.0:52024
>>> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.21.0:58671
>>> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription
>>> request for HTTP framework 'default'
>>> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
>>> principal 'test-principal' to receive offers for role '*'
>>> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
>>> 'default' with checkpointing disabled and capabilities [  ]
>>> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources
>>> available to allocate!
>>> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers to
>>> send out!
>>> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation
>>> for 0 slaves in 278800ns
>>> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event
>>> SUBSCRIBED received from master@172.17.21.0:52024
>>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event HEARTBEAT
>>> received from master@172.17.21.0:52024
>>> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring
>>> HEARTBEAT event
>>> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to
>>> master@172.17.21.0:52024
>>> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.21.0:58672
>>> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call for
>>> framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
>>> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
>>> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
>>> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
>>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>>> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received from
>>> master. The master closed the event stream
>>> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
>>> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in 41.862895ms
>>> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in
>>> 28393ns
>>> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db
>>> in 3402ns
>>> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys in
>>> the db in 424ns
>>> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with log
>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
>>> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
>>> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
>>> received a broadcasted recover request from (11270)@172.17.21.0:52024
>>> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover response
>>> from a replica in EMPTY status
>>> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status to
>>> STARTING
>>> I1201 13:13:39.842226 30310 master.cpp:365] Master
>>> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
>>> 172.17.21.0:52024
>>> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup: --acls=""
>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>> --authenticate="false" --authenticate_slaves="true"
>>> --authenticators="crammd5" --authorizers="local"
>>> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
>>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>>> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
>>> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
>>> unauthenticated frameworks to register
>>> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
>>> authenticated slaves to register
>>> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials for
>>> authentication from '/tmp/BZ8798/credentials'
>>> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
>>> authenticator
>>> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
>>> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist given
>>> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized
>>> hierarchical allocator process
>>> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader is
>>> master@172.17.21.0:52024 with id f1235cbb-2af4-4048-8379-cb927ec30140
>>> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading
>>> master!
>>> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
>>> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
>>> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 154.538135ms
>>> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status to
>>> STARTING
>>> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING
>>> status
>>> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING status
>>> received a broadcasted recover request from (11272)@172.17.21.0:52024
>>> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover response
>>> from a replica in STARTING status
>>> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status to
>>> VOTING
>>> 2015-12-01
>>> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
>>> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection refused):
>>> server refused to accept the client
>>> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 153.522723ms
>>> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status to
>>> VOTING
>>> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the
>>> Paxos group
>>> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
>>> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
>>> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit
>>> promise request from (11273)@172.17.21.0:52024 with proposal 1
>>> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 30.196031ms
>>> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
>>> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator attempting
>>> to fill missing positions
>>> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit
>>> promise request from (11274)@172.17.21.0:52024 for position 0 with
>>> proposal 2
>>> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8 bytes)
>>> to leveldb took 21.637902ms
>>> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
>>> request for position 0 from (11275)@172.17.21.0:52024
>>> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from
>>> leveldb took 57423ns
>>> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14
>>> bytes) to leveldb took 23.068613ms
>>> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
>>> notice for position 0 from @0.0.0.0:0
>>> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 24.122945ms
>>> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
>>> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP action
>>> at position 0
>>> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
>>> position 0
>>> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from
>>> leveldb took 51852ns
>>> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched the
>>> registry (0B) in 406.404096ms
>>> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in
>>> 32037ns; attempting to update the 'registry'
>>> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171 bytes
>>> to the log
>>> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator attempting
>>> to write APPEND action at position 1
>>> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
>>> request for position 1 from (11276)@172.17.21.0:52024
>>> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190
>>> bytes) to leveldb took 38.855065ms
>>> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
>>> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
>>> notice for position 1 from @0.0.0.0:0
>>> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192
>>> bytes) to leveldb took 28.359915ms
>>> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
>>> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND
>>> action at position 1
>>> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated the
>>> 'registry' in 77.036288ms
>>> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
>>> registrar
>>> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the log
>>> to 1
>>> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator attempting
>>> to write TRUNCATE action at position 2
>>> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
>>> request for position 2 from (11277)@172.17.21.0:52024
>>> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from the
>>> Registry (132B) ; allowing 10mins for slaves to re-register
>>> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery is
>>> not supported yet
>>> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 29.65284ms
>>> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
>>> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
>>> notice for position 2 from @0.0.0.0:0
>>> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18
>>> bytes) to leveldb took 31.661429ms
>>> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from
>>> leveldb took 75229ns
>>> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
>>> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
>>> action at position 2
>>> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
>>> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
>>> master@172.17.21.0:52024
>>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call to
>>> master@172.17.21.0:52024
>>> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.21.0:58674
>>> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription
>>> request for HTTP framework 'default'
>>> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
>>> principal 'test-principal' to receive offers for role '*'
>>> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
>>> 'default' with checkpointing disabled and capabilities [  ]
>>> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources
>>> available to allocate!
>>> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers to
>>> send out!
>>> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation
>>> for 0 slaves in 88470ns
>>> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event
>>> SUBSCRIBED received from master@172.17.21.0:52024
>>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event HEARTBEAT
>>> received from master@172.17.21.0:52024
>>> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring
>>> HEARTBEAT event
>>> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to
>>> master@172.17.21.0:52024
>>> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.21.0:58675
>>> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call for
>>> framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
>>> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
>>> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
>>> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
>>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>>> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received from
>>> master. The master closed the event stream
>>> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
>>> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>>>
>>> [----------] Global test environment tear-down
>>> [==========] 860 tests from 115 test cases ran. (821953 ms total)
>>> [  PASSED  ] 858 tests.
>>> [  FAILED  ] 2 tests, listed below:
>>> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
>>> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>>>
>>>  2 FAILED TESTS
>>>   YOU HAVE 7 DISABLED TESTS
>>>
>>> make[4]: *** [check-local] Error 1
>>> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>> make[3]: *** [check-am] Error 2
>>> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>> make[2]: *** [check] Error 2
>>> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>>> make[1]: *** [check-recursive] Error 1
>>> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
>>> make: *** [distcheck] Error 1
>>> + docker rmi mesos-1448971321-13066
>>> Untagged: mesos-1448971321-13066:latest
>>> Deleted: 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
>>> Deleted: 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
>>> Deleted: b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
>>> Deleted: d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
>>> Deleted: 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
>>> Deleted: d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
>>> Deleted: 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
>>> Deleted: 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
>>> Deleted: daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
>>> Deleted: 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
>>> Deleted: 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
>>> Deleted: 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
>>> Deleted: 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
>>> Build step 'Execute shell' marked build as failure
>>>
>>
>>

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

[Michael Park <mp...@mesosphere.io>]

Yep, I'll look into it once I get back to a computer.

On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <be...@gmail.com>
wrote:

> Michael, this looks like https://issues.apache.org/jira/browse/MESOS-3907?
> Can you please triage it?
>
> Tim, I've added details to
> https://issues.apache.org/jira/browse/MESOS-4024. Can you please triage
> it? Also, the test takes 16 seconds to finish? :(
>
> On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
> jenkins@builds.apache.org> wrote:
>
>> See <
>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
>> >
>>
>> Changes:
>>
>> [mpark] Introduced filter for non-revocable resources.
>>
>> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>>
>> ------------------------------------------
>> [...truncated 150475 lines...]
>> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
>> for gc 6.9999984545837days in the future
>> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
>> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
>> for gc 6.99999845272days in the future
>> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing status
>> update streams for framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up
>> status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
>> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
>> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
>> [ RUN      ] ContentType/SchedulerTest.Request/0
>> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
>> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in 36.820837ms
>> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in
>> 28745ns
>> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db in
>> 4075ns
>> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys in
>> the db in 506ns
>> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
>> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
>> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
>> received a broadcasted recover request from (11259)@172.17.21.0:52024
>> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover response
>> from a replica in EMPTY status
>> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status to
>> STARTING
>> I1201 13:13:39.310650 30317 master.cpp:365] Master
>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
>> 172.17.21.0:52024
>> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
>> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
>> unauthenticated frameworks to register
>> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
>> authenticated slaves to register
>> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials for
>> authentication from '/tmp/ZHbR13/credentials'
>> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
>> authenticator
>> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
>> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized
>> hierarchical allocator process
>> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist given
>> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 26.131683ms
>> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status to
>> STARTING
>> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING status
>> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader is
>> master@172.17.21.0:52024 with id afc8b3bb-8b30-42f9-bb3d-e218e05c5758
>> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading
>> master!
>> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
>> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
>> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING status
>> received a broadcasted recover request from (11261)@172.17.21.0:52024
>> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover response
>> from a replica in STARTING status
>> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status to
>> VOTING
>> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 19.367885ms
>> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status to
>> VOTING
>> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the
>> Paxos group
>> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
>> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
>> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit
>> promise request from (11262)@172.17.21.0:52024 with proposal 1
>> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 20.816751ms
>> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
>> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator attempting
>> to fill missing positions
>> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit
>> promise request from (11263)@172.17.21.0:52024 for position 0 with
>> proposal 2
>> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8 bytes)
>> to leveldb took 21.553914ms
>> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
>> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
>> request for position 0 from (11264)@172.17.21.0:52024
>> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from
>> leveldb took 138547ns
>> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14 bytes)
>> to leveldb took 21.856586ms
>> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
>> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 22.672674ms
>> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
>> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP action
>> at position 0
>> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
>> position 0
>> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from
>> leveldb took 54316ns
>> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched the
>> registry (0B) in 135.67488ms
>> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in
>> 58207ns; attempting to update the 'registry'
>> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171 bytes
>> to the log
>> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator attempting
>> to write APPEND action at position 1
>> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
>> request for position 1 from (11265)@172.17.21.0:52024
>> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190
>> bytes) to leveldb took 24.470564ms
>> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
>> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192
>> bytes) to leveldb took 23.909555ms
>> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
>> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND
>> action at position 1
>> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated the
>> 'registry' in 56.57088ms
>> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
>> registrar
>> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the log
>> to 1
>> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from the
>> Registry (132B) ; allowing 10mins for slaves to re-register
>> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery is
>> not supported yet
>> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
>> request for position 2 from (11266)@172.17.21.0:52024
>> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 26.14166ms
>> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
>> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18 bytes)
>> to leveldb took 22.715014ms
>> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from
>> leveldb took 68387ns
>> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
>> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
>> action at position 2
>> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
>> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
>> master@172.17.21.0:52024
>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call to
>> master@172.17.21.0:52024
>> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.21.0:58671
>> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription
>> request for HTTP framework 'default'
>> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [  ]
>> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources available
>> to allocate!
>> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers to
>> send out!
>> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation
>> for 0 slaves in 278800ns
>> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event SUBSCRIBED
>> received from master@172.17.21.0:52024
>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event HEARTBEAT
>> received from master@172.17.21.0:52024
>> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring
>> HEARTBEAT event
>> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to
>> master@172.17.21.0:52024
>> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.21.0:58672
>> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call for
>> framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
>> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
>> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
>> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
>> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
>> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received from
>> master. The master closed the event stream
>> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
>> [ RUN      ] ContentType/SchedulerTest.Request/1
>> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
>> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in 41.862895ms
>> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in
>> 28393ns
>> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db in
>> 3402ns
>> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys in
>> the db in 424ns
>> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
>> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
>> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
>> received a broadcasted recover request from (11270)@172.17.21.0:52024
>> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover response
>> from a replica in EMPTY status
>> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status to
>> STARTING
>> I1201 13:13:39.842226 30310 master.cpp:365] Master
>> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
>> 172.17.21.0:52024
>> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
>> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
>> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
>> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
>> unauthenticated frameworks to register
>> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
>> authenticated slaves to register
>> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials for
>> authentication from '/tmp/BZ8798/credentials'
>> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
>> authenticator
>> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
>> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist given
>> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized
>> hierarchical allocator process
>> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader is
>> master@172.17.21.0:52024 with id f1235cbb-2af4-4048-8379-cb927ec30140
>> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading
>> master!
>> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
>> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
>> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 154.538135ms
>> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status to
>> STARTING
>> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING status
>> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING status
>> received a broadcasted recover request from (11272)@172.17.21.0:52024
>> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover response
>> from a replica in STARTING status
>> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status to
>> VOTING
>> 2015-12-01
>> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
>> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection refused):
>> server refused to accept the client
>> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 153.522723ms
>> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status to
>> VOTING
>> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the
>> Paxos group
>> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
>> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
>> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit
>> promise request from (11273)@172.17.21.0:52024 with proposal 1
>> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 30.196031ms
>> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
>> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator attempting
>> to fill missing positions
>> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit
>> promise request from (11274)@172.17.21.0:52024 for position 0 with
>> proposal 2
>> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8 bytes)
>> to leveldb took 21.637902ms
>> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
>> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
>> request for position 0 from (11275)@172.17.21.0:52024
>> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from
>> leveldb took 57423ns
>> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14 bytes)
>> to leveldb took 23.068613ms
>> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
>> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 24.122945ms
>> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
>> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP action
>> at position 0
>> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
>> position 0
>> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from
>> leveldb took 51852ns
>> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched the
>> registry (0B) in 406.404096ms
>> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in
>> 32037ns; attempting to update the 'registry'
>> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171 bytes
>> to the log
>> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator attempting
>> to write APPEND action at position 1
>> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
>> request for position 1 from (11276)@172.17.21.0:52024
>> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190
>> bytes) to leveldb took 38.855065ms
>> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
>> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192
>> bytes) to leveldb took 28.359915ms
>> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
>> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND
>> action at position 1
>> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated the
>> 'registry' in 77.036288ms
>> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
>> registrar
>> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the log
>> to 1
>> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
>> request for position 2 from (11277)@172.17.21.0:52024
>> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from the
>> Registry (132B) ; allowing 10mins for slaves to re-register
>> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery is
>> not supported yet
>> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 29.65284ms
>> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
>> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18 bytes)
>> to leveldb took 31.661429ms
>> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from
>> leveldb took 75229ns
>> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
>> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
>> action at position 2
>> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
>> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
>> master@172.17.21.0:52024
>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call to
>> master@172.17.21.0:52024
>> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.21.0:58674
>> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription
>> request for HTTP framework 'default'
>> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [  ]
>> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources available
>> to allocate!
>> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers to
>> send out!
>> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation
>> for 0 slaves in 88470ns
>> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event SUBSCRIBED
>> received from master@172.17.21.0:52024
>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event HEARTBEAT
>> received from master@172.17.21.0:52024
>> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring
>> HEARTBEAT event
>> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to
>> master@172.17.21.0:52024
>> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.21.0:58675
>> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call for
>> framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
>> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
>> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
>> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
>> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
>> f1235cbb-2af4-4048-8379-cb927ec30140-0000
>> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received from
>> master. The master closed the event stream
>> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
>> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>>
>> [----------] Global test environment tear-down
>> [==========] 860 tests from 115 test cases ran. (821953 ms total)
>> [  PASSED  ] 858 tests.
>> [  FAILED  ] 2 tests, listed below:
>> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
>> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>>
>>  2 FAILED TESTS
>>   YOU HAVE 7 DISABLED TESTS
>>
>> make[4]: *** [check-local] Error 1
>> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>> make[3]: *** [check-am] Error 2
>> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>> make[2]: *** [check] Error 2
>> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
>> make[1]: *** [check-recursive] Error 1
>> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
>> make: *** [distcheck] Error 1
>> + docker rmi mesos-1448971321-13066
>> Untagged: mesos-1448971321-13066:latest
>> Deleted: 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
>> Deleted: 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
>> Deleted: b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
>> Deleted: d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
>> Deleted: 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
>> Deleted: d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
>> Deleted: 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
>> Deleted: 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
>> Deleted: daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
>> Deleted: 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
>> Deleted: 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
>> Deleted: 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
>> Deleted: 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
>> Build step 'Execute shell' marked build as failure
>>
>
>

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

[Benjamin Mahler <be...@gmail.com>]

Michael, this looks like https://issues.apache.org/jira/browse/MESOS-3907?
Can you please triage it?

Tim, I've added details to https://issues.apache.org/jira/browse/MESOS-4024.
Can you please triage it? Also, the test takes 16 seconds to finish? :(

On Tue, Dec 1, 2015 at 5:13 AM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:

> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1298/changes
> >
>
> Changes:
>
> [mpark] Introduced filter for non-revocable resources.
>
> [mpark] Updated codebase to use `nonRevocable()` where appropriate.
>
> ------------------------------------------
> [...truncated 150475 lines...]
> I1201 13:13:39.133826 30312 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000/executors/default'
> for gc 6.9999984545837days in the future
> I1201 13:13:39.133921 30312 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_TaiosT/slaves/4ee094e8-02a9-49de-b684-4d65e1dbab3a-S0/frameworks/4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000'
> for gc 6.99999845272days in the future
> I1201 13:13:39.134052 30312 status_update_manager.cpp:282] Closing status
> update streams for framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
> I1201 13:13:39.134109 30312 status_update_manager.cpp:528] Cleaning up
> status update stream for task df889fba-4ec5-48a2-bb6a-b82e50d823ee of
> framework 4ee094e8-02a9-49de-b684-4d65e1dbab3a-0000
> [       OK ] ContentType/SchedulerTest.Message/1 (620 ms)
> [ RUN      ] ContentType/SchedulerTest.Request/0
> I1201 13:13:39.249682 30288 leveldb.cpp:174] Opened db in 108.293757ms
> I1201 13:13:39.286597 30288 leveldb.cpp:181] Compacted db in 36.820837ms
> I1201 13:13:39.286878 30288 leveldb.cpp:196] Created db iterator in 28745ns
> I1201 13:13:39.287019 30288 leveldb.cpp:202] Seeked to beginning of db in
> 4075ns
> I1201 13:13:39.287135 30288 leveldb.cpp:271] Iterated through 0 keys in
> the db in 506ns
> I1201 13:13:39.287328 30288 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1201 13:13:39.288477 30322 recover.cpp:447] Starting replica recovery
> I1201 13:13:39.288979 30322 recover.cpp:473] Replica is in EMPTY status
> I1201 13:13:39.291091 30307 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11259)@172.17.21.0:52024
> I1201 13:13:39.292063 30322 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1201 13:13:39.292816 30322 recover.cpp:564] Updating replica status to
> STARTING
> I1201 13:13:39.310650 30317 master.cpp:365] Master
> afc8b3bb-8b30-42f9-bb3d-e218e05c5758 (fa812f474cf4) started on
> 172.17.21.0:52024
> I1201 13:13:39.310979 30317 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/ZHbR13/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/ZHbR13/master" --zk_session_timeout="10secs"
> I1201 13:13:39.311813 30317 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1201 13:13:39.311939 30317 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1201 13:13:39.312055 30317 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/ZHbR13/credentials'
> I1201 13:13:39.312582 30317 master.cpp:456] Using default 'crammd5'
> authenticator
> I1201 13:13:39.313015 30317 master.cpp:493] Authorization enabled
> I1201 13:13:39.314574 30318 hierarchical.cpp:162] Initialized hierarchical
> allocator process
> I1201 13:13:39.314782 30318 whitelist_watcher.cpp:77] No whitelist given
> I1201 13:13:39.319352 30314 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 26.131683ms
> I1201 13:13:39.319414 30314 replica.cpp:321] Persisted replica status to
> STARTING
> I1201 13:13:39.319850 30321 recover.cpp:473] Replica is in STARTING status
> I1201 13:13:39.321290 30317 master.cpp:1637] The newly elected leader is
> master@172.17.21.0:52024 with id afc8b3bb-8b30-42f9-bb3d-e218e05c5758
> I1201 13:13:39.321327 30317 master.cpp:1650] Elected as the leading master!
> I1201 13:13:39.321348 30317 master.cpp:1395] Recovering from registrar
> I1201 13:13:39.321607 30310 registrar.cpp:307] Recovering registrar
> I1201 13:13:39.322362 30308 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11261)@172.17.21.0:52024
> I1201 13:13:39.323760 30308 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1201 13:13:39.324712 30308 recover.cpp:564] Updating replica status to
> VOTING
> I1201 13:13:39.344523 30322 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 19.367885ms
> I1201 13:13:39.344609 30322 replica.cpp:321] Persisted replica status to
> VOTING
> I1201 13:13:39.344866 30322 recover.cpp:578] Successfully joined the Paxos
> group
> I1201 13:13:39.345070 30322 recover.cpp:462] Recover process terminated
> I1201 13:13:39.346154 30313 log.cpp:659] Attempting to start the writer
> I1201 13:13:39.348711 30322 replica.cpp:494] Replica received implicit
> promise request from (11262)@172.17.21.0:52024 with proposal 1
> I1201 13:13:39.369730 30322 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 20.816751ms
> I1201 13:13:39.369815 30322 replica.cpp:343] Persisted promised to 1
> I1201 13:13:39.371050 30322 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1201 13:13:39.373064 30322 replica.cpp:389] Replica received explicit
> promise request from (11263)@172.17.21.0:52024 for position 0 with
> proposal 2
> I1201 13:13:39.394858 30322 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 21.553914ms
> I1201 13:13:39.394944 30322 replica.cpp:713] Persisted action at 0
> I1201 13:13:39.397928 30320 replica.cpp:538] Replica received write
> request for position 0 from (11264)@172.17.21.0:52024
> I1201 13:13:39.398121 30320 leveldb.cpp:436] Reading position from leveldb
> took 138547ns
> I1201 13:13:39.420068 30320 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 21.856586ms
> I1201 13:13:39.420158 30320 replica.cpp:713] Persisted action at 0
> I1201 13:13:39.421149 30320 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1201 13:13:39.445179 30320 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 22.672674ms
> I1201 13:13:39.445264 30320 replica.cpp:713] Persisted action at 0
> I1201 13:13:39.445297 30320 replica.cpp:698] Replica learned NOP action at
> position 0
> I1201 13:13:39.446470 30317 log.cpp:675] Writer started with ending
> position 0
> I1201 13:13:39.448024 30317 leveldb.cpp:436] Reading position from leveldb
> took 54316ns
> I1201 13:13:39.457492 30314 registrar.cpp:340] Successfully fetched the
> registry (0B) in 135.67488ms
> I1201 13:13:39.457800 30314 registrar.cpp:439] Applied 1 operations in
> 58207ns; attempting to update the 'registry'
> I1201 13:13:39.461079 30307 log.cpp:683] Attempting to append 171 bytes to
> the log
> I1201 13:13:39.461359 30307 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1201 13:13:39.462405 30315 replica.cpp:538] Replica received write
> request for position 1 from (11265)@172.17.21.0:52024
> I1201 13:13:39.486935 30315 leveldb.cpp:341] Persisting action (190 bytes)
> to leveldb took 24.470564ms
> I1201 13:13:39.487015 30315 replica.cpp:713] Persisted action at 1
> I1201 13:13:39.488296 30311 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1201 13:13:39.512262 30311 leveldb.cpp:341] Persisting action (192 bytes)
> to leveldb took 23.909555ms
> I1201 13:13:39.512357 30311 replica.cpp:713] Persisted action at 1
> I1201 13:13:39.512395 30311 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1201 13:13:39.514448 30315 registrar.cpp:484] Successfully updated the
> 'registry' in 56.57088ms
> I1201 13:13:39.514611 30315 registrar.cpp:370] Successfully recovered
> registrar
> I1201 13:13:39.514899 30315 log.cpp:702] Attempting to truncate the log to
> 1
> I1201 13:13:39.515408 30321 master.cpp:1447] Recovered 0 slaves from the
> Registry (132B) ; allowing 10mins for slaves to re-register
> I1201 13:13:39.515601 30321 hierarchical.cpp:174] Allocator recovery is
> not supported yet
> I1201 13:13:39.515990 30311 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1201 13:13:39.519279 30322 replica.cpp:538] Replica received write
> request for position 2 from (11266)@172.17.21.0:52024
> I1201 13:13:39.545508 30322 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 26.14166ms
> I1201 13:13:39.545591 30322 replica.cpp:713] Persisted action at 2
> I1201 13:13:39.547046 30311 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1201 13:13:39.570616 30311 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 22.715014ms
> I1201 13:13:39.570765 30311 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 68387ns
> I1201 13:13:39.570792 30311 replica.cpp:713] Persisted action at 2
> I1201 13:13:39.570827 30311 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1201 13:13:39.581652 30288 scheduler.cpp:154] Version: 0.27.0
> I1201 13:13:39.582635 30316 scheduler.cpp:236] New master detected at
> master@172.17.21.0:52024
> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.21.0:52024
> I1201 13:13:39.603560 30314 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1201 13:13:39.603791 30314 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.21.0:58671
> I1201 13:13:39.604238 30314 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1201 13:13:39.604393 30314 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1201 13:13:39.605239 30308 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [  ]
> I1201 13:13:39.605927 30308 hierarchical.cpp:220] Added framework
> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
> I1201 13:13:39.606053 30308 hierarchical.cpp:1062] No resources available
> to allocate!
> I1201 13:13:39.606200 30308 hierarchical.cpp:1155] No inverse offers to
> send out!
> I1201 13:13:39.606287 30308 hierarchical.cpp:957] Performed allocation for
> 0 slaves in 278800ns
> I1201 13:13:39.606386 30308 master.hpp:1542] Sending heartbeat to
> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
> I1201 13:13:39.610970 30313 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.21.0:52024
> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.21.0:52024
> I1201 13:13:39.612519 30313 master_maintenance_tests.cpp:172] Ignoring
> HEARTBEAT event
> I1201 13:13:39.613566 30322 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.21.0:52024
> I1201 13:13:39.616225 30314 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1201 13:13:39.616303 30314 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.21.0:58672
> I1201 13:13:39.616457 30314 master.cpp:2646] Processing REQUEST call for
> framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000 (default)
> I1201 13:13:39.616729 30314 hierarchical.cpp:492] Received resource
> request from framework afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
> I1201 13:13:39.618245 30316 master.cpp:938] Master terminating
> I1201 13:13:39.618852 30316 hierarchical.cpp:260] Removed framework
> afc8b3bb-8b30-42f9-bb3d-e218e05c5758-0000
> E1201 13:13:39.625231 30320 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [       OK ] ContentType/SchedulerTest.Request/0 (537 ms)
> [ RUN      ] ContentType/SchedulerTest.Request/1
> I1201 13:13:39.781806 30288 leveldb.cpp:174] Opened db in 103.133011ms
> I1201 13:13:39.823753 30288 leveldb.cpp:181] Compacted db in 41.862895ms
> I1201 13:13:39.824023 30288 leveldb.cpp:196] Created db iterator in 28393ns
> I1201 13:13:39.824106 30288 leveldb.cpp:202] Seeked to beginning of db in
> 3402ns
> I1201 13:13:39.824213 30288 leveldb.cpp:271] Iterated through 0 keys in
> the db in 424ns
> I1201 13:13:39.824362 30288 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1201 13:13:39.825932 30314 recover.cpp:447] Starting replica recovery
> I1201 13:13:39.829377 30312 recover.cpp:473] Replica is in EMPTY status
> I1201 13:13:39.831303 30321 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11270)@172.17.21.0:52024
> I1201 13:13:39.831908 30312 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1201 13:13:39.832659 30308 recover.cpp:564] Updating replica status to
> STARTING
> I1201 13:13:39.842226 30310 master.cpp:365] Master
> f1235cbb-2af4-4048-8379-cb927ec30140 (fa812f474cf4) started on
> 172.17.21.0:52024
> I1201 13:13:39.842382 30310 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/BZ8798/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --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.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/BZ8798/master" --zk_session_timeout="10secs"
> I1201 13:13:39.843057 30310 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1201 13:13:39.843125 30310 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1201 13:13:39.843212 30310 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/BZ8798/credentials'
> I1201 13:13:39.854533 30310 master.cpp:456] Using default 'crammd5'
> authenticator
> I1201 13:13:39.854784 30310 master.cpp:493] Authorization enabled
> I1201 13:13:39.855118 30316 whitelist_watcher.cpp:77] No whitelist given
> I1201 13:13:39.855201 30307 hierarchical.cpp:162] Initialized hierarchical
> allocator process
> I1201 13:13:39.857786 30308 master.cpp:1637] The newly elected leader is
> master@172.17.21.0:52024 with id f1235cbb-2af4-4048-8379-cb927ec30140
> I1201 13:13:39.857890 30308 master.cpp:1650] Elected as the leading master!
> I1201 13:13:39.858012 30308 master.cpp:1395] Recovering from registrar
> I1201 13:13:39.858214 30321 registrar.cpp:307] Recovering registrar
> I1201 13:13:39.987658 30312 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 154.538135ms
> I1201 13:13:39.987746 30312 replica.cpp:321] Persisted replica status to
> STARTING
> I1201 13:13:39.988102 30309 recover.cpp:473] Replica is in STARTING status
> I1201 13:13:39.989462 30312 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11272)@172.17.21.0:52024
> I1201 13:13:39.989681 30319 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1201 13:13:39.990227 30315 recover.cpp:564] Updating replica status to
> VOTING
> 2015-12-01
> 13:13:40,008:30288(0x2b1492486700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:38773] zk retcode=-4, errno=111(Connection refused):
> server refused to accept the client
> I1201 13:13:40.144186 30315 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 153.522723ms
> I1201 13:13:40.144278 30315 replica.cpp:321] Persisted replica status to
> VOTING
> I1201 13:13:40.144538 30315 recover.cpp:578] Successfully joined the Paxos
> group
> I1201 13:13:40.144737 30315 recover.cpp:462] Recover process terminated
> I1201 13:13:40.145442 30315 log.cpp:659] Attempting to start the writer
> I1201 13:13:40.147264 30315 replica.cpp:494] Replica received implicit
> promise request from (11273)@172.17.21.0:52024 with proposal 1
> I1201 13:13:40.177583 30315 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 30.196031ms
> I1201 13:13:40.177677 30315 replica.cpp:343] Persisted promised to 1
> I1201 13:13:40.178966 30315 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1201 13:13:40.180896 30308 replica.cpp:389] Replica received explicit
> promise request from (11274)@172.17.21.0:52024 for position 0 with
> proposal 2
> I1201 13:13:40.202713 30308 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 21.637902ms
> I1201 13:13:40.202796 30308 replica.cpp:713] Persisted action at 0
> I1201 13:13:40.204490 30315 replica.cpp:538] Replica received write
> request for position 0 from (11275)@172.17.21.0:52024
> I1201 13:13:40.204653 30315 leveldb.cpp:436] Reading position from leveldb
> took 57423ns
> I1201 13:13:40.227870 30315 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 23.068613ms
> I1201 13:13:40.227952 30315 replica.cpp:713] Persisted action at 0
> I1201 13:13:40.228931 30315 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1201 13:13:40.253105 30315 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 24.122945ms
> I1201 13:13:40.253196 30315 replica.cpp:713] Persisted action at 0
> I1201 13:13:40.253229 30315 replica.cpp:698] Replica learned NOP action at
> position 0
> I1201 13:13:40.261934 30319 log.cpp:675] Writer started with ending
> position 0
> I1201 13:13:40.263435 30319 leveldb.cpp:436] Reading position from leveldb
> took 51852ns
> I1201 13:13:40.264667 30319 registrar.cpp:340] Successfully fetched the
> registry (0B) in 406.404096ms
> I1201 13:13:40.264837 30319 registrar.cpp:439] Applied 1 operations in
> 32037ns; attempting to update the 'registry'
> I1201 13:13:40.266000 30319 log.cpp:683] Attempting to append 171 bytes to
> the log
> I1201 13:13:40.266196 30319 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1201 13:13:40.267202 30319 replica.cpp:538] Replica received write
> request for position 1 from (11276)@172.17.21.0:52024
> I1201 13:13:40.306112 30319 leveldb.cpp:341] Persisting action (190 bytes)
> to leveldb took 38.855065ms
> I1201 13:13:40.306206 30319 replica.cpp:713] Persisted action at 1
> I1201 13:13:40.311035 30312 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1201 13:13:40.339625 30312 leveldb.cpp:341] Persisting action (192 bytes)
> to leveldb took 28.359915ms
> I1201 13:13:40.339715 30312 replica.cpp:713] Persisted action at 1
> I1201 13:13:40.339754 30312 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1201 13:13:40.341955 30309 registrar.cpp:484] Successfully updated the
> 'registry' in 77.036288ms
> I1201 13:13:40.342131 30309 registrar.cpp:370] Successfully recovered
> registrar
> I1201 13:13:40.342241 30313 log.cpp:702] Attempting to truncate the log to
> 1
> I1201 13:13:40.342452 30313 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1201 13:13:40.343538 30317 replica.cpp:538] Replica received write
> request for position 2 from (11277)@172.17.21.0:52024
> I1201 13:13:40.344214 30309 master.cpp:1447] Recovered 0 slaves from the
> Registry (132B) ; allowing 10mins for slaves to re-register
> I1201 13:13:40.344310 30309 hierarchical.cpp:174] Allocator recovery is
> not supported yet
> I1201 13:13:40.373257 30317 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 29.65284ms
> I1201 13:13:40.373345 30317 replica.cpp:713] Persisted action at 2
> I1201 13:13:40.374905 30317 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1201 13:13:40.406621 30317 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 31.661429ms
> I1201 13:13:40.406776 30317 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 75229ns
> I1201 13:13:40.406803 30317 replica.cpp:713] Persisted action at 2
> I1201 13:13:40.406837 30317 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1201 13:13:40.416626 30288 scheduler.cpp:154] Version: 0.27.0
> I1201 13:13:40.418025 30317 scheduler.cpp:236] New master detected at
> master@172.17.21.0:52024
> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.21.0:52024
> I1201 13:13:40.421510 30309 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1201 13:13:40.421581 30309 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.21.0:58674
> I1201 13:13:40.421988 30309 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1201 13:13:40.422067 30309 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1201 13:13:40.422495 30309 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [  ]
> I1201 13:13:40.423338 30314 hierarchical.cpp:220] Added framework
> f1235cbb-2af4-4048-8379-cb927ec30140-0000
> I1201 13:13:40.423396 30314 hierarchical.cpp:1062] No resources available
> to allocate!
> I1201 13:13:40.423430 30314 hierarchical.cpp:1155] No inverse offers to
> send out!
> I1201 13:13:40.423452 30314 hierarchical.cpp:957] Performed allocation for
> 0 slaves in 88470ns
> I1201 13:13:40.423480 30314 master.hpp:1542] Sending heartbeat to
> f1235cbb-2af4-4048-8379-cb927ec30140-0000
> I1201 13:13:40.430143 30314 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.21.0:52024
> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.21.0:52024
> I1201 13:13:40.432108 30311 master_maintenance_tests.cpp:172] Ignoring
> HEARTBEAT event
> I1201 13:13:40.432857 30310 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.21.0:52024
> I1201 13:13:40.435833 30318 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1201 13:13:40.435905 30318 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.21.0:58675
> I1201 13:13:40.436228 30318 master.cpp:2646] Processing REQUEST call for
> framework f1235cbb-2af4-4048-8379-cb927ec30140-0000 (default)
> I1201 13:13:40.436463 30318 hierarchical.cpp:492] Received resource
> request from framework f1235cbb-2af4-4048-8379-cb927ec30140-0000
> I1201 13:13:40.437156 30312 master.cpp:938] Master terminating
> I1201 13:13:40.438628 30315 hierarchical.cpp:260] Removed framework
> f1235cbb-2af4-4048-8379-cb927ec30140-0000
> E1201 13:13:40.449956 30313 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [       OK ] ContentType/SchedulerTest.Request/1 (802 ms)
> [----------] 22 tests from ContentType/SchedulerTest (17087 ms total)
>
> [----------] Global test environment tear-down
> [==========] 860 tests from 115 test cases ran. (821953 ms total)
> [  PASSED  ] 858 tests.
> [  FAILED  ] 2 tests, listed below:
> [  FAILED  ] HealthCheckTest.CheckCommandTimeout
> [  FAILED  ] PersistentVolumeTest.SlaveRecovery
>
>  2 FAILED TESTS
>   YOU HAVE 7 DISABLED TESTS
>
> make[4]: *** [check-local] Error 1
> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
> make[3]: *** [check-am] Error 2
> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
> make[2]: *** [check] Error 2
> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
> make[1]: *** [check-recursive] Error 1
> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
> make: *** [distcheck] Error 1
> + docker rmi mesos-1448971321-13066
> Untagged: mesos-1448971321-13066:latest
> Deleted: 579aa525055c35024667aa78495048284fba4c5b49fb29fe980cee2e96c770d2
> Deleted: 0db305a5ce4fab92189e208ed71bd4fa9ec3acbb71c95d6a3c4c6b59aebedb67
> Deleted: b0a83d7dfef1dc69cf7d71ba729a02710bc99981b0cb6d43535ac104a55ec6da
> Deleted: d4411f19e3629671ec868c87b65a0174ceeeabd93128b3930deef45bebd0ff65
> Deleted: 31f86a323ee991dfb2bfd36e4d4203b69c5ae9d734d7905e3f8c7b6c7d6dfc49
> Deleted: d9b9b23572603497de08cf63696bf0cd3749860e66750c66731b677283000283
> Deleted: 15578fc9ac532712bd7e77464040842070ad5173f41b9b1a6b2be80808c9d79a
> Deleted: 8ca7b89d896734687e673149f0cf7e5655929b799d4d176ee2500a8cc0b7b698
> Deleted: daf73a12ec932adb3289e201f1e580c423b3835c71682443e802d91830529e97
> Deleted: 0952f15e04c7ae8aafee3024a0ce6bebec38dad0274ee3b3d0ec4dab46d35bab
> Deleted: 72393d27e5e3eaa9ecaa1f381756032c7c96acbb1dc3b249d11b9f1b0557128d
> Deleted: 561e3d0690dbac5b70bc45e9beeb186c71fe0343e7dde3c682b67cb569deae5b
> Deleted: 095e8a4bc98539ee10c69a064e32a0bb58693c3c649fcb20e39fae8449003b7f
> Build step 'Execute shell' marked build as failure
>