https://issues.apache.org/jira/browse/MESOS-3907
On Fri, Dec 4, 2015 at 1:10 AM, Michael Park <[email protected]> wrote: > +Jie Yu <[email protected]> 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 <[email protected]> > wrote: > >> Thank you sir! >> >> On Thu, Dec 3, 2015 at 7:45 PM, Michael Park <[email protected]> wrote: >> >>> Yep, I'll look into it once I get back to a computer. >>> >>> On Thu, Dec 3, 2015, 10:44 PM Benjamin Mahler <[email protected]> >>> 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 < >>>> [email protected]> 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 [email protected]: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 >>>>> [email protected]:52024 >>>>> I1201 13:13:39.596861 30321 scheduler.cpp:298] Sending SUBSCRIBE call >>>>> to [email protected]: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 [email protected]:52024 >>>>> I1201 13:13:39.611906 30313 scheduler.cpp:457] Enqueuing event >>>>> HEARTBEAT received from [email protected]: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 >>>>> [email protected]: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 [email protected]: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 >>>>> [email protected]:52024 >>>>> I1201 13:13:40.419311 30311 scheduler.cpp:298] Sending SUBSCRIBE call >>>>> to [email protected]: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 [email protected]:52024 >>>>> I1201 13:13:40.431577 30311 scheduler.cpp:457] Enqueuing event >>>>> HEARTBEAT received from [email protected]: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 >>>>> [email protected]: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 >>>>> >>>> >>>> >>
