You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2015/10/13 11:58:03 UTC
Build failed in Jenkins: Mesos » gcc,--verbose,ubuntu:14.04,docker||Hadoop #921
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/921/changes>
Changes:
[mpark] Changed secret field in `Credential` from `bytes` to `string`
------------------------------------------
[...truncated 137953 lines...]
I1013 09:58:37.518443 29148 replica.cpp:681] Persisted action at 4
I1013 09:58:37.518486 29148 replica.cpp:666] Replica learned TRUNCATE action at position 4
I1013 09:58:37.520514 29117 slave.cpp:592] Slave terminating
I1013 09:58:37.520606 29117 slave.cpp:2002] Asked to shut down framework ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000 by @0.0.0.0:0
I1013 09:58:37.520650 29117 slave.cpp:2027] Shutting down framework ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
I1013 09:58:37.520720 29117 slave.cpp:3839] Shutting down executor 'default' of framework ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
[ OK ] ContentType/SchedulerTest.Message/1 (661 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
Using temporary directory '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw'
I1013 09:58:37.645978 29117 leveldb.cpp:176] Opened db in 117.641437ms
I1013 09:58:37.696156 29117 leveldb.cpp:183] Compacted db in 50.096056ms
I1013 09:58:37.696295 29117 leveldb.cpp:198] Created db iterator in 24234ns
I1013 09:58:37.696311 29117 leveldb.cpp:204] Seeked to beginning of db in 2925ns
I1013 09:58:37.696319 29117 leveldb.cpp:273] Iterated through 0 keys in the db in 230ns
I1013 09:58:37.696372 29117 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1013 09:58:37.696943 29142 recover.cpp:449] Starting replica recovery
I1013 09:58:37.697202 29142 recover.cpp:475] Replica is in EMPTY status
I1013 09:58:37.698290 29143 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (9952)@172.17.5.161:57074
I1013 09:58:37.698782 29151 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1013 09:58:37.699270 29139 recover.cpp:566] Updating replica status to STARTING
I1013 09:58:37.700114 29143 master.cpp:376] Master 2cf0ec01-605e-47cd-8893-5fa5c02d778b (071521b41cca) started on 172.17.5.161:57074
I1013 09:58:37.700139 29143 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/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.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/master" --zk_session_timeout="10secs"
I1013 09:58:37.700453 29143 master.cpp:425] Master allowing unauthenticated frameworks to register
I1013 09:58:37.700474 29143 master.cpp:428] Master only allowing authenticated slaves to register
I1013 09:58:37.700487 29143 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/credentials'
I1013 09:58:37.700753 29143 master.cpp:467] Using default 'crammd5' authenticator
I1013 09:58:37.700875 29143 master.cpp:504] Authorization enabled
I1013 09:58:37.701099 29140 whitelist_watcher.cpp:79] No whitelist given
I1013 09:58:37.701118 29139 hierarchical.hpp:468] Initialized hierarchical allocator process
I1013 09:58:37.702304 29142 master.cpp:1603] The newly elected leader is master@172.17.5.161:57074 with id 2cf0ec01-605e-47cd-8893-5fa5c02d778b
I1013 09:58:37.702337 29142 master.cpp:1616] Elected as the leading master!
I1013 09:58:37.702352 29142 master.cpp:1376] Recovering from registrar
I1013 09:58:37.702494 29146 registrar.cpp:309] Recovering registrar
I1013 09:58:37.736212 29141 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 36.329384ms
I1013 09:58:37.736285 29141 replica.cpp:323] Persisted replica status to STARTING
I1013 09:58:37.736630 29145 recover.cpp:475] Replica is in STARTING status
I1013 09:58:37.737884 29138 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (9953)@172.17.5.161:57074
I1013 09:58:37.738332 29149 recover.cpp:195] Received a recover response from a replica in STARTING status
I1013 09:58:37.738726 29141 recover.cpp:566] Updating replica status to VOTING
I1013 09:58:37.763111 29136 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 24.221295ms
I1013 09:58:37.763201 29136 replica.cpp:323] Persisted replica status to VOTING
I1013 09:58:37.763413 29139 recover.cpp:580] Successfully joined the Paxos group
I1013 09:58:37.763625 29139 recover.cpp:464] Recover process terminated
I1013 09:58:37.764195 29151 log.cpp:661] Attempting to start the writer
I1013 09:58:37.765425 29140 replica.cpp:478] Replica received implicit promise request from (9954)@172.17.5.161:57074 with proposal 1
I1013 09:58:37.788241 29140 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 22.76316ms
I1013 09:58:37.788431 29140 replica.cpp:345] Persisted promised to 1
I1013 09:58:37.789913 29142 coordinator.cpp:231] Coordinator attemping to fill missing position
I1013 09:58:37.791985 29140 replica.cpp:378] Replica received explicit promise request from (9955)@172.17.5.161:57074 for position 0 with proposal 2
I1013 09:58:37.820113 29140 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 27.989977ms
I1013 09:58:37.820233 29140 replica.cpp:681] Persisted action at 0
I1013 09:58:37.822196 29143 replica.cpp:512] Replica received write request for position 0 from (9956)@172.17.5.161:57074
I1013 09:58:37.822310 29143 leveldb.cpp:438] Reading position from leveldb took 58661ns
I1013 09:58:37.852663 29143 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 30.257433ms
I1013 09:58:37.852749 29143 replica.cpp:681] Persisted action at 0
I1013 09:58:37.853713 29149 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
I1013 09:58:37.890965 29149 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 37.192627ms
I1013 09:58:37.891055 29149 replica.cpp:681] Persisted action at 0
I1013 09:58:37.891088 29149 replica.cpp:666] Replica learned NOP action at position 0
I1013 09:58:37.891880 29138 log.cpp:677] Writer started with ending position 0
I1013 09:58:37.893005 29144 leveldb.cpp:438] Reading position from leveldb took 58276ns
I1013 09:58:37.893924 29137 registrar.cpp:342] Successfully fetched the registry (0B) in 191.308032ms
I1013 09:58:37.894063 29137 registrar.cpp:441] Applied 1 operations in 35330ns; attempting to update the 'registry'
I1013 09:58:37.894876 29147 log.cpp:685] Attempting to append 176 bytes to the log
I1013 09:58:37.894999 29139 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I1013 09:58:37.895704 29146 replica.cpp:512] Replica received write request for position 1 from (9957)@172.17.5.161:57074
I1013 09:58:37.936381 29146 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 40.621032ms
I1013 09:58:37.936467 29146 replica.cpp:681] Persisted action at 1
I1013 09:58:37.937479 29136 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
I1013 09:58:37.974557 29136 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 37.028107ms
I1013 09:58:37.974647 29136 replica.cpp:681] Persisted action at 1
I1013 09:58:37.974684 29136 replica.cpp:666] Replica learned APPEND action at position 1
I1013 09:58:37.976876 29145 registrar.cpp:486] Successfully updated the 'registry' in 82.680064ms
I1013 09:58:37.977061 29145 registrar.cpp:372] Successfully recovered registrar
I1013 09:58:37.977252 29137 log.cpp:704] Attempting to truncate the log to 1
I1013 09:58:37.977591 29137 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I1013 09:58:37.979133 29137 replica.cpp:512] Replica received write request for position 2 from (9958)@172.17.5.161:57074
I1013 09:58:37.979919 29145 master.cpp:1413] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I1013 09:58:38.016520 29137 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 37.215953ms
I1013 09:58:38.016607 29137 replica.cpp:681] Persisted action at 2
I1013 09:58:38.017614 29146 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
I1013 09:58:38.053596 29146 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 35.926384ms
I1013 09:58:38.053742 29146 leveldb.cpp:401] Deleting ~1 keys from leveldb took 64962ns
I1013 09:58:38.053766 29146 replica.cpp:681] Persisted action at 2
I1013 09:58:38.053799 29146 replica.cpp:666] Replica learned TRUNCATE action at position 2
I1013 09:58:38.062036 29117 scheduler.cpp:157] Version: 0.26.0
I1013 09:58:38.062861 29140 scheduler.cpp:240] New master detected at master@172.17.5.161:57074
I1013 09:58:38.064096 29140 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.5.161:57074
I1013 09:58:38.066210 29139 process.cpp:3075] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1013 09:58:38.066473 29139 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.5.161:45379
I1013 09:58:38.066685 29139 master.cpp:1865] Received subscription request for HTTP framework 'default'
I1013 09:58:38.066777 29139 master.cpp:1642] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1013 09:58:38.067019 29139 master.cpp:1957] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1013 09:58:38.067353 29145 hierarchical.hpp:515] Added framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
I1013 09:58:38.067387 29145 hierarchical.hpp:1328] No resources available to allocate!
I1013 09:58:38.067409 29145 hierarchical.hpp:1423] No inverse offers to send out!
I1013 09:58:38.067423 29139 master.hpp:1431] Sending heartbeat to 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
I1013 09:58:38.067425 29145 hierarchical.hpp:1223] Performed allocation for 0 slaves in 48435ns
I1013 09:58:38.068274 29145 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.5.161:57074
I1013 09:58:38.068778 29145 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.5.161:57074
I1013 09:58:38.069406 29149 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1013 09:58:38.069494 29145 scheduler.cpp:302] Sending REQUEST call to master@172.17.5.161:57074
I1013 09:58:38.070850 29148 process.cpp:3075] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1013 09:58:38.071027 29148 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.5.161:45380
I1013 09:58:38.071138 29148 master.cpp:2618] Processing REQUEST call for framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000 (default)
I1013 09:58:38.071317 29146 hierarchical.hpp:801] Received resource request from framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
I1013 09:58:38.071578 29147 master.cpp:919] Master terminating
I1013 09:58:38.071739 29140 hierarchical.hpp:552] Removed framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
E1013 09:58:38.074120 29136 scheduler.cpp:435] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (552 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
Using temporary directory '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ'
I1013 09:58:38.189395 29117 leveldb.cpp:176] Opened db in 109.310773ms
I1013 09:58:38.206452 29117 leveldb.cpp:183] Compacted db in 16.987516ms
I1013 09:58:38.206538 29117 leveldb.cpp:198] Created db iterator in 24050ns
I1013 09:58:38.206555 29117 leveldb.cpp:204] Seeked to beginning of db in 2900ns
I1013 09:58:38.206562 29117 leveldb.cpp:273] Iterated through 0 keys in the db in 205ns
I1013 09:58:38.206611 29117 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1013 09:58:38.207154 29140 recover.cpp:449] Starting replica recovery
I1013 09:58:38.207386 29148 recover.cpp:475] Replica is in EMPTY status
I1013 09:58:38.209626 29143 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (9962)@172.17.5.161:57074
I1013 09:58:38.209715 29143 master.cpp:376] Master f2c7f910-a186-48a6-bfcf-11403bd8fcd3 (071521b41cca) started on 172.17.5.161:57074
I1013 09:58:38.209735 29143 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/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.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/master" --zk_session_timeout="10secs"
I1013 09:58:38.210049 29143 master.cpp:425] Master allowing unauthenticated frameworks to register
I1013 09:58:38.210054 29147 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1013 09:58:38.210069 29143 master.cpp:428] Master only allowing authenticated slaves to register
I1013 09:58:38.210080 29143 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/credentials'
I1013 09:58:38.210433 29143 master.cpp:467] Using default 'crammd5' authenticator
I1013 09:58:38.210556 29143 master.cpp:504] Authorization enabled
I1013 09:58:38.210608 29139 recover.cpp:566] Updating replica status to STARTING
I1013 09:58:38.210783 29137 whitelist_watcher.cpp:79] No whitelist given
I1013 09:58:38.210793 29136 hierarchical.hpp:468] Initialized hierarchical allocator process
I1013 09:58:38.211930 29148 master.cpp:1603] The newly elected leader is master@172.17.5.161:57074 with id f2c7f910-a186-48a6-bfcf-11403bd8fcd3
I1013 09:58:38.211958 29148 master.cpp:1616] Elected as the leading master!
I1013 09:58:38.211974 29148 master.cpp:1376] Recovering from registrar
I1013 09:58:38.212134 29151 registrar.cpp:309] Recovering registrar
I1013 09:58:38.254777 29137 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 43.732952ms
I1013 09:58:38.254858 29137 replica.cpp:323] Persisted replica status to STARTING
I1013 09:58:38.255199 29151 recover.cpp:475] Replica is in STARTING status
I1013 09:58:38.257005 29144 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (9963)@172.17.5.161:57074
I1013 09:58:38.257325 29147 recover.cpp:195] Received a recover response from a replica in STARTING status
I1013 09:58:38.257869 29144 recover.cpp:566] Updating replica status to VOTING
I1013 09:58:38.298324 29147 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 40.289075ms
I1013 09:58:38.298395 29147 replica.cpp:323] Persisted replica status to VOTING
I1013 09:58:38.298615 29144 recover.cpp:580] Successfully joined the Paxos group
I1013 09:58:38.299027 29144 recover.cpp:464] Recover process terminated
I1013 09:58:38.299420 29146 log.cpp:661] Attempting to start the writer
I1013 09:58:38.300607 29149 replica.cpp:478] Replica received implicit promise request from (9964)@172.17.5.161:57074 with proposal 1
I1013 09:58:38.340129 29149 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 39.4719ms
I1013 09:58:38.340225 29149 replica.cpp:345] Persisted promised to 1
I1013 09:58:38.341013 29138 coordinator.cpp:231] Coordinator attemping to fill missing position
I1013 09:58:38.342344 29148 replica.cpp:378] Replica received explicit promise request from (9965)@172.17.5.161:57074 for position 0 with proposal 2
I1013 09:58:38.381867 29148 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 39.460457ms
I1013 09:58:38.381945 29148 replica.cpp:681] Persisted action at 0
I1013 09:58:38.383513 29149 replica.cpp:512] Replica received write request for position 0 from (9966)@172.17.5.161:57074
I1013 09:58:38.383710 29149 leveldb.cpp:438] Reading position from leveldb took 39304ns
I1013 09:58:38.421689 29149 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 37.822366ms
I1013 09:58:38.421775 29149 replica.cpp:681] Persisted action at 0
I1013 09:58:38.422787 29149 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
I1013 09:58:38.451143 29149 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 28.302809ms
I1013 09:58:38.451225 29149 replica.cpp:681] Persisted action at 0
I1013 09:58:38.451256 29149 replica.cpp:666] Replica learned NOP action at position 0
I1013 09:58:38.452137 29144 log.cpp:677] Writer started with ending position 0
I1013 09:58:38.453286 29143 leveldb.cpp:438] Reading position from leveldb took 50882ns
I1013 09:58:38.454264 29143 registrar.cpp:342] Successfully fetched the registry (0B) in 241.997056ms
I1013 09:58:38.454391 29143 registrar.cpp:441] Applied 1 operations in 26172ns; attempting to update the 'registry'
I1013 09:58:38.455090 29150 log.cpp:685] Attempting to append 176 bytes to the log
I1013 09:58:38.455220 29147 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I1013 09:58:38.455912 29136 replica.cpp:512] Replica received write request for position 1 from (9967)@172.17.5.161:57074
I1013 09:58:38.476287 29136 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 20.327366ms
I1013 09:58:38.476354 29136 replica.cpp:681] Persisted action at 1
I1013 09:58:38.477073 29142 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
I1013 09:58:38.501523 29142 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 24.401714ms
I1013 09:58:38.501598 29142 replica.cpp:681] Persisted action at 1
I1013 09:58:38.501629 29142 replica.cpp:666] Replica learned APPEND action at position 1
I1013 09:58:38.503021 29136 registrar.cpp:486] Successfully updated the 'registry' in 48.561152ms
I1013 09:58:38.503144 29136 registrar.cpp:372] Successfully recovered registrar
I1013 09:58:38.503325 29149 log.cpp:704] Attempting to truncate the log to 1
I1013 09:58:38.503463 29141 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I1013 09:58:38.503535 29142 master.cpp:1413] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I1013 09:58:38.504396 29147 replica.cpp:512] Replica received write request for position 2 from (9968)@172.17.5.161:57074
I1013 09:58:38.526587 29147 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 22.124468ms
I1013 09:58:38.526669 29147 replica.cpp:681] Persisted action at 2
I1013 09:58:38.528002 29145 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
I1013 09:58:38.551810 29145 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 23.749842ms
I1013 09:58:38.551961 29145 leveldb.cpp:401] Deleting ~1 keys from leveldb took 68370ns
I1013 09:58:38.551997 29145 replica.cpp:681] Persisted action at 2
I1013 09:58:38.552042 29145 replica.cpp:666] Replica learned TRUNCATE action at position 2
I1013 09:58:38.555748 29117 scheduler.cpp:157] Version: 0.26.0
I1013 09:58:38.556823 29145 scheduler.cpp:240] New master detected at master@172.17.5.161:57074
I1013 09:58:38.558246 29144 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.5.161:57074
I1013 09:58:38.561697 29143 process.cpp:3075] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1013 09:58:38.562072 29143 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.5.161:45381
I1013 09:58:38.562728 29143 master.cpp:1865] Received subscription request for HTTP framework 'default'
I1013 09:58:38.562892 29143 master.cpp:1642] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1013 09:58:38.563436 29140 master.cpp:1957] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1013 09:58:38.564118 29140 hierarchical.hpp:515] Added framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
I1013 09:58:38.564157 29140 hierarchical.hpp:1328] No resources available to allocate!
I1013 09:58:38.564244 29140 hierarchical.hpp:1423] No inverse offers to send out!
I1013 09:58:38.564265 29140 hierarchical.hpp:1223] Performed allocation for 0 slaves in 119906ns
I1013 09:58:38.564215 29141 master.hpp:1431] Sending heartbeat to f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
I1013 09:58:38.566124 29141 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.5.161:57074
I1013 09:58:38.566568 29141 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.5.161:57074
I1013 09:58:38.567932 29151 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1013 09:58:38.568320 29151 scheduler.cpp:302] Sending REQUEST call to master@172.17.5.161:57074
I1013 09:58:38.570888 29148 process.cpp:3075] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1013 09:58:38.571157 29148 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.5.161:45382
I1013 09:58:38.571723 29148 master.cpp:2618] Processing REQUEST call for framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000 (default)
I1013 09:58:38.571964 29148 hierarchical.hpp:801] Received resource request from framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
I1013 09:58:38.572737 29117 master.cpp:919] Master terminating
I1013 09:58:38.573541 29139 hierarchical.hpp:552] Removed framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
E1013 09:58:38.577641 29138 scheduler.cpp:435] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (502 ms)
[----------] 22 tests from ContentType/SchedulerTest (15540 ms total)
[----------] Global test environment tear-down
[==========] 807 tests from 110 test cases ran. (707196 ms total)
[ PASSED ] 806 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] ReservationEndpointsTest.AvailableResources
1 FAILED TEST
YOU HAVE 7 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.26.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1444727831-8911
Untagged: mesos-1444727831-8911:latest
Deleted: 84ca9f5fa2ebd0191688b2ffcf76296d0d991d75a9ae0a313ffea8956c39233b
Deleted: 26d8f638e61064921b2c9008e2ea232707a161101585a4ac60d173815a5b0176
Deleted: ab5864c334fdd1a5109558fcca2a93290ec3082f218757f60c56ab87a7c04d05
Deleted: 4d0c18b835dff04df5821b406448028a9492ad0e4597832f9441e30394b81ce0
Deleted: 3c6294ab4f00a8eb0c58c676cabebaf879134d32f685779c4fab08f3734cf693
Deleted: e2d06781179ea19561e24165e591b5353d68bed1677c8dea584a474c270cfc63
Deleted: 0896a0a04d6eafe255b59faf6a2983028dbed9e0a306d4584ea332133180e368
Deleted: 0fd565ae22f94bb38710569901763af3282dc00a886b404d0b2d40c18758ddf3
Deleted: aaca0877e4aa23770f37ca62ce596485fa8bde10905d61dfb4ecdfdf1ef8a4bf
Deleted: 8600cc9b3224a42d9d19bcfcb34537727b5c5ca8ab7a4925f793a6eb02475970
Deleted: 107c8af22de6519b0463cd13813b1455f2b341d42ad4edec2eb6bbffa2860397
Deleted: eecb9099b675455188f9dc0966dfa6b5f2d6a311983a87fad44647f86713acae
Deleted: 13edeb98704cf7aae557086b50dede5496d9663d85a30b6595f51df76559fa84
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos » gcc,--verbose,ubuntu:14.04,docker||Hadoop #922
Posted by 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/922/changes>
Re: Build failed in Jenkins: Mesos » gcc,--verbose,ubuntu:14.04,docker||Hadoop #921
Posted by Michael Park <mc...@gmail.com>.
Posted a fix up for review: https://reviews.apache.org/r/39300/
On Tue, Oct 13, 2015 at 10:25 PM Benjamin Mahler <be...@gmail.com>
wrote:
> +michael
>
> Could you triage this test failure?
>
> On Tue, Oct 13, 2015 at 2:58 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/921/changes
>> >
>>
>> Changes:
>>
>> [mpark] Changed secret field in `Credential` from `bytes` to `string`
>>
>> ------------------------------------------
>> [...truncated 137953 lines...]
>> I1013 09:58:37.518443 29148 replica.cpp:681] Persisted action at 4
>> I1013 09:58:37.518486 29148 replica.cpp:666] Replica learned TRUNCATE
>> action at position 4
>> I1013 09:58:37.520514 29117 slave.cpp:592] Slave terminating
>> I1013 09:58:37.520606 29117 slave.cpp:2002] Asked to shut down framework
>> ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000 by @0.0.0.0:0
>> I1013 09:58:37.520650 29117 slave.cpp:2027] Shutting down framework
>> ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
>> I1013 09:58:37.520720 29117 slave.cpp:3839] Shutting down executor
>> 'default' of framework ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
>> [ OK ] ContentType/SchedulerTest.Message/1 (661 ms)
>> [ RUN ] ContentType/SchedulerTest.Request/0
>> Using temporary directory
>> '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw'
>> I1013 09:58:37.645978 29117 leveldb.cpp:176] Opened db in 117.641437ms
>> I1013 09:58:37.696156 29117 leveldb.cpp:183] Compacted db in 50.096056ms
>> I1013 09:58:37.696295 29117 leveldb.cpp:198] Created db iterator in
>> 24234ns
>> I1013 09:58:37.696311 29117 leveldb.cpp:204] Seeked to beginning of db in
>> 2925ns
>> I1013 09:58:37.696319 29117 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 230ns
>> I1013 09:58:37.696372 29117 replica.cpp:746] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1013 09:58:37.696943 29142 recover.cpp:449] Starting replica recovery
>> I1013 09:58:37.697202 29142 recover.cpp:475] Replica is in EMPTY status
>> I1013 09:58:37.698290 29143 replica.cpp:642] Replica in EMPTY status
>> received a broadcasted recover request from (9952)@172.17.5.161:57074
>> I1013 09:58:37.698782 29151 recover.cpp:195] Received a recover response
>> from a replica in EMPTY status
>> I1013 09:58:37.699270 29139 recover.cpp:566] Updating replica status to
>> STARTING
>> I1013 09:58:37.700114 29143 master.cpp:376] Master
>> 2cf0ec01-605e-47cd-8893-5fa5c02d778b (071521b41cca) started on
>> 172.17.5.161:57074
>> I1013 09:58:37.700139 29143 master.cpp:378] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/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.26.0/_inst/share/mesos/webui"
>> --work_dir="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/master"
>> --zk_session_timeout="10secs"
>> I1013 09:58:37.700453 29143 master.cpp:425] Master allowing
>> unauthenticated frameworks to register
>> I1013 09:58:37.700474 29143 master.cpp:428] Master only allowing
>> authenticated slaves to register
>> I1013 09:58:37.700487 29143 credentials.hpp:37] Loading credentials for
>> authentication from
>> '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/credentials'
>> I1013 09:58:37.700753 29143 master.cpp:467] Using default 'crammd5'
>> authenticator
>> I1013 09:58:37.700875 29143 master.cpp:504] Authorization enabled
>> I1013 09:58:37.701099 29140 whitelist_watcher.cpp:79] No whitelist given
>> I1013 09:58:37.701118 29139 hierarchical.hpp:468] Initialized
>> hierarchical allocator process
>> I1013 09:58:37.702304 29142 master.cpp:1603] The newly elected leader is
>> master@172.17.5.161:57074 with id 2cf0ec01-605e-47cd-8893-5fa5c02d778b
>> I1013 09:58:37.702337 29142 master.cpp:1616] Elected as the leading
>> master!
>> I1013 09:58:37.702352 29142 master.cpp:1376] Recovering from registrar
>> I1013 09:58:37.702494 29146 registrar.cpp:309] Recovering registrar
>> I1013 09:58:37.736212 29141 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 36.329384ms
>> I1013 09:58:37.736285 29141 replica.cpp:323] Persisted replica status to
>> STARTING
>> I1013 09:58:37.736630 29145 recover.cpp:475] Replica is in STARTING status
>> I1013 09:58:37.737884 29138 replica.cpp:642] Replica in STARTING status
>> received a broadcasted recover request from (9953)@172.17.5.161:57074
>> I1013 09:58:37.738332 29149 recover.cpp:195] Received a recover response
>> from a replica in STARTING status
>> I1013 09:58:37.738726 29141 recover.cpp:566] Updating replica status to
>> VOTING
>> I1013 09:58:37.763111 29136 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 24.221295ms
>> I1013 09:58:37.763201 29136 replica.cpp:323] Persisted replica status to
>> VOTING
>> I1013 09:58:37.763413 29139 recover.cpp:580] Successfully joined the
>> Paxos group
>> I1013 09:58:37.763625 29139 recover.cpp:464] Recover process terminated
>> I1013 09:58:37.764195 29151 log.cpp:661] Attempting to start the writer
>> I1013 09:58:37.765425 29140 replica.cpp:478] Replica received implicit
>> promise request from (9954)@172.17.5.161:57074 with proposal 1
>> I1013 09:58:37.788241 29140 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 22.76316ms
>> I1013 09:58:37.788431 29140 replica.cpp:345] Persisted promised to 1
>> I1013 09:58:37.789913 29142 coordinator.cpp:231] Coordinator attemping to
>> fill missing position
>> I1013 09:58:37.791985 29140 replica.cpp:378] Replica received explicit
>> promise request from (9955)@172.17.5.161:57074 for position 0 with
>> proposal 2
>> I1013 09:58:37.820113 29140 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 27.989977ms
>> I1013 09:58:37.820233 29140 replica.cpp:681] Persisted action at 0
>> I1013 09:58:37.822196 29143 replica.cpp:512] Replica received write
>> request for position 0 from (9956)@172.17.5.161:57074
>> I1013 09:58:37.822310 29143 leveldb.cpp:438] Reading position from
>> leveldb took 58661ns
>> I1013 09:58:37.852663 29143 leveldb.cpp:343] Persisting action (14 bytes)
>> to leveldb took 30.257433ms
>> I1013 09:58:37.852749 29143 replica.cpp:681] Persisted action at 0
>> I1013 09:58:37.853713 29149 replica.cpp:660] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1013 09:58:37.890965 29149 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 37.192627ms
>> I1013 09:58:37.891055 29149 replica.cpp:681] Persisted action at 0
>> I1013 09:58:37.891088 29149 replica.cpp:666] Replica learned NOP action
>> at position 0
>> I1013 09:58:37.891880 29138 log.cpp:677] Writer started with ending
>> position 0
>> I1013 09:58:37.893005 29144 leveldb.cpp:438] Reading position from
>> leveldb took 58276ns
>> I1013 09:58:37.893924 29137 registrar.cpp:342] Successfully fetched the
>> registry (0B) in 191.308032ms
>> I1013 09:58:37.894063 29137 registrar.cpp:441] Applied 1 operations in
>> 35330ns; attempting to update the 'registry'
>> I1013 09:58:37.894876 29147 log.cpp:685] Attempting to append 176 bytes
>> to the log
>> I1013 09:58:37.894999 29139 coordinator.cpp:341] Coordinator attempting
>> to write APPEND action at position 1
>> I1013 09:58:37.895704 29146 replica.cpp:512] Replica received write
>> request for position 1 from (9957)@172.17.5.161:57074
>> I1013 09:58:37.936381 29146 leveldb.cpp:343] Persisting action (195
>> bytes) to leveldb took 40.621032ms
>> I1013 09:58:37.936467 29146 replica.cpp:681] Persisted action at 1
>> I1013 09:58:37.937479 29136 replica.cpp:660] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1013 09:58:37.974557 29136 leveldb.cpp:343] Persisting action (197
>> bytes) to leveldb took 37.028107ms
>> I1013 09:58:37.974647 29136 replica.cpp:681] Persisted action at 1
>> I1013 09:58:37.974684 29136 replica.cpp:666] Replica learned APPEND
>> action at position 1
>> I1013 09:58:37.976876 29145 registrar.cpp:486] Successfully updated the
>> 'registry' in 82.680064ms
>> I1013 09:58:37.977061 29145 registrar.cpp:372] Successfully recovered
>> registrar
>> I1013 09:58:37.977252 29137 log.cpp:704] Attempting to truncate the log
>> to 1
>> I1013 09:58:37.977591 29137 coordinator.cpp:341] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1013 09:58:37.979133 29137 replica.cpp:512] Replica received write
>> request for position 2 from (9958)@172.17.5.161:57074
>> I1013 09:58:37.979919 29145 master.cpp:1413] Recovered 0 slaves from the
>> Registry (137B) ; allowing 10mins for slaves to re-register
>> I1013 09:58:38.016520 29137 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 37.215953ms
>> I1013 09:58:38.016607 29137 replica.cpp:681] Persisted action at 2
>> I1013 09:58:38.017614 29146 replica.cpp:660] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1013 09:58:38.053596 29146 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 35.926384ms
>> I1013 09:58:38.053742 29146 leveldb.cpp:401] Deleting ~1 keys from
>> leveldb took 64962ns
>> I1013 09:58:38.053766 29146 replica.cpp:681] Persisted action at 2
>> I1013 09:58:38.053799 29146 replica.cpp:666] Replica learned TRUNCATE
>> action at position 2
>> I1013 09:58:38.062036 29117 scheduler.cpp:157] Version: 0.26.0
>> I1013 09:58:38.062861 29140 scheduler.cpp:240] New master detected at
>> master@172.17.5.161:57074
>> I1013 09:58:38.064096 29140 scheduler.cpp:302] Sending SUBSCRIBE call to
>> master@172.17.5.161:57074
>> I1013 09:58:38.066210 29139 process.cpp:3075] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1013 09:58:38.066473 29139 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.5.161:45379
>> I1013 09:58:38.066685 29139 master.cpp:1865] Received subscription
>> request for HTTP framework 'default'
>> I1013 09:58:38.066777 29139 master.cpp:1642] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1013 09:58:38.067019 29139 master.cpp:1957] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [ ]
>> I1013 09:58:38.067353 29145 hierarchical.hpp:515] Added framework
>> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
>> I1013 09:58:38.067387 29145 hierarchical.hpp:1328] No resources available
>> to allocate!
>> I1013 09:58:38.067409 29145 hierarchical.hpp:1423] No inverse offers to
>> send out!
>> I1013 09:58:38.067423 29139 master.hpp:1431] Sending heartbeat to
>> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
>> I1013 09:58:38.067425 29145 hierarchical.hpp:1223] Performed allocation
>> for 0 slaves in 48435ns
>> I1013 09:58:38.068274 29145 scheduler.cpp:461] Enqueuing event SUBSCRIBED
>> received from master@172.17.5.161:57074
>> I1013 09:58:38.068778 29145 scheduler.cpp:461] Enqueuing event HEARTBEAT
>> received from master@172.17.5.161:57074
>> I1013 09:58:38.069406 29149 master_maintenance_tests.cpp:179] Ignoring
>> HEARTBEAT event
>> I1013 09:58:38.069494 29145 scheduler.cpp:302] Sending REQUEST call to
>> master@172.17.5.161:57074
>> I1013 09:58:38.070850 29148 process.cpp:3075] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1013 09:58:38.071027 29148 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.5.161:45380
>> I1013 09:58:38.071138 29148 master.cpp:2618] Processing REQUEST call for
>> framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000 (default)
>> I1013 09:58:38.071317 29146 hierarchical.hpp:801] Received resource
>> request from framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
>> I1013 09:58:38.071578 29147 master.cpp:919] Master terminating
>> I1013 09:58:38.071739 29140 hierarchical.hpp:552] Removed framework
>> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
>> E1013 09:58:38.074120 29136 scheduler.cpp:435] End-Of-File received from
>> master. The master closed the event stream
>> [ OK ] ContentType/SchedulerTest.Request/0 (552 ms)
>> [ RUN ] ContentType/SchedulerTest.Request/1
>> Using temporary directory
>> '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ'
>> I1013 09:58:38.189395 29117 leveldb.cpp:176] Opened db in 109.310773ms
>> I1013 09:58:38.206452 29117 leveldb.cpp:183] Compacted db in 16.987516ms
>> I1013 09:58:38.206538 29117 leveldb.cpp:198] Created db iterator in
>> 24050ns
>> I1013 09:58:38.206555 29117 leveldb.cpp:204] Seeked to beginning of db in
>> 2900ns
>> I1013 09:58:38.206562 29117 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 205ns
>> I1013 09:58:38.206611 29117 replica.cpp:746] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1013 09:58:38.207154 29140 recover.cpp:449] Starting replica recovery
>> I1013 09:58:38.207386 29148 recover.cpp:475] Replica is in EMPTY status
>> I1013 09:58:38.209626 29143 replica.cpp:642] Replica in EMPTY status
>> received a broadcasted recover request from (9962)@172.17.5.161:57074
>> I1013 09:58:38.209715 29143 master.cpp:376] Master
>> f2c7f910-a186-48a6-bfcf-11403bd8fcd3 (071521b41cca) started on
>> 172.17.5.161:57074
>> I1013 09:58:38.209735 29143 master.cpp:378] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/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.26.0/_inst/share/mesos/webui"
>> --work_dir="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/master"
>> --zk_session_timeout="10secs"
>> I1013 09:58:38.210049 29143 master.cpp:425] Master allowing
>> unauthenticated frameworks to register
>> I1013 09:58:38.210054 29147 recover.cpp:195] Received a recover response
>> from a replica in EMPTY status
>> I1013 09:58:38.210069 29143 master.cpp:428] Master only allowing
>> authenticated slaves to register
>> I1013 09:58:38.210080 29143 credentials.hpp:37] Loading credentials for
>> authentication from
>> '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/credentials'
>> I1013 09:58:38.210433 29143 master.cpp:467] Using default 'crammd5'
>> authenticator
>> I1013 09:58:38.210556 29143 master.cpp:504] Authorization enabled
>> I1013 09:58:38.210608 29139 recover.cpp:566] Updating replica status to
>> STARTING
>> I1013 09:58:38.210783 29137 whitelist_watcher.cpp:79] No whitelist given
>> I1013 09:58:38.210793 29136 hierarchical.hpp:468] Initialized
>> hierarchical allocator process
>> I1013 09:58:38.211930 29148 master.cpp:1603] The newly elected leader is
>> master@172.17.5.161:57074 with id f2c7f910-a186-48a6-bfcf-11403bd8fcd3
>> I1013 09:58:38.211958 29148 master.cpp:1616] Elected as the leading
>> master!
>> I1013 09:58:38.211974 29148 master.cpp:1376] Recovering from registrar
>> I1013 09:58:38.212134 29151 registrar.cpp:309] Recovering registrar
>> I1013 09:58:38.254777 29137 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 43.732952ms
>> I1013 09:58:38.254858 29137 replica.cpp:323] Persisted replica status to
>> STARTING
>> I1013 09:58:38.255199 29151 recover.cpp:475] Replica is in STARTING status
>> I1013 09:58:38.257005 29144 replica.cpp:642] Replica in STARTING status
>> received a broadcasted recover request from (9963)@172.17.5.161:57074
>> I1013 09:58:38.257325 29147 recover.cpp:195] Received a recover response
>> from a replica in STARTING status
>> I1013 09:58:38.257869 29144 recover.cpp:566] Updating replica status to
>> VOTING
>> I1013 09:58:38.298324 29147 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 40.289075ms
>> I1013 09:58:38.298395 29147 replica.cpp:323] Persisted replica status to
>> VOTING
>> I1013 09:58:38.298615 29144 recover.cpp:580] Successfully joined the
>> Paxos group
>> I1013 09:58:38.299027 29144 recover.cpp:464] Recover process terminated
>> I1013 09:58:38.299420 29146 log.cpp:661] Attempting to start the writer
>> I1013 09:58:38.300607 29149 replica.cpp:478] Replica received implicit
>> promise request from (9964)@172.17.5.161:57074 with proposal 1
>> I1013 09:58:38.340129 29149 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 39.4719ms
>> I1013 09:58:38.340225 29149 replica.cpp:345] Persisted promised to 1
>> I1013 09:58:38.341013 29138 coordinator.cpp:231] Coordinator attemping to
>> fill missing position
>> I1013 09:58:38.342344 29148 replica.cpp:378] Replica received explicit
>> promise request from (9965)@172.17.5.161:57074 for position 0 with
>> proposal 2
>> I1013 09:58:38.381867 29148 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 39.460457ms
>> I1013 09:58:38.381945 29148 replica.cpp:681] Persisted action at 0
>> I1013 09:58:38.383513 29149 replica.cpp:512] Replica received write
>> request for position 0 from (9966)@172.17.5.161:57074
>> I1013 09:58:38.383710 29149 leveldb.cpp:438] Reading position from
>> leveldb took 39304ns
>> I1013 09:58:38.421689 29149 leveldb.cpp:343] Persisting action (14 bytes)
>> to leveldb took 37.822366ms
>> I1013 09:58:38.421775 29149 replica.cpp:681] Persisted action at 0
>> I1013 09:58:38.422787 29149 replica.cpp:660] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1013 09:58:38.451143 29149 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 28.302809ms
>> I1013 09:58:38.451225 29149 replica.cpp:681] Persisted action at 0
>> I1013 09:58:38.451256 29149 replica.cpp:666] Replica learned NOP action
>> at position 0
>> I1013 09:58:38.452137 29144 log.cpp:677] Writer started with ending
>> position 0
>> I1013 09:58:38.453286 29143 leveldb.cpp:438] Reading position from
>> leveldb took 50882ns
>> I1013 09:58:38.454264 29143 registrar.cpp:342] Successfully fetched the
>> registry (0B) in 241.997056ms
>> I1013 09:58:38.454391 29143 registrar.cpp:441] Applied 1 operations in
>> 26172ns; attempting to update the 'registry'
>> I1013 09:58:38.455090 29150 log.cpp:685] Attempting to append 176 bytes
>> to the log
>> I1013 09:58:38.455220 29147 coordinator.cpp:341] Coordinator attempting
>> to write APPEND action at position 1
>> I1013 09:58:38.455912 29136 replica.cpp:512] Replica received write
>> request for position 1 from (9967)@172.17.5.161:57074
>> I1013 09:58:38.476287 29136 leveldb.cpp:343] Persisting action (195
>> bytes) to leveldb took 20.327366ms
>> I1013 09:58:38.476354 29136 replica.cpp:681] Persisted action at 1
>> I1013 09:58:38.477073 29142 replica.cpp:660] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1013 09:58:38.501523 29142 leveldb.cpp:343] Persisting action (197
>> bytes) to leveldb took 24.401714ms
>> I1013 09:58:38.501598 29142 replica.cpp:681] Persisted action at 1
>> I1013 09:58:38.501629 29142 replica.cpp:666] Replica learned APPEND
>> action at position 1
>> I1013 09:58:38.503021 29136 registrar.cpp:486] Successfully updated the
>> 'registry' in 48.561152ms
>> I1013 09:58:38.503144 29136 registrar.cpp:372] Successfully recovered
>> registrar
>> I1013 09:58:38.503325 29149 log.cpp:704] Attempting to truncate the log
>> to 1
>> I1013 09:58:38.503463 29141 coordinator.cpp:341] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1013 09:58:38.503535 29142 master.cpp:1413] Recovered 0 slaves from the
>> Registry (137B) ; allowing 10mins for slaves to re-register
>> I1013 09:58:38.504396 29147 replica.cpp:512] Replica received write
>> request for position 2 from (9968)@172.17.5.161:57074
>> I1013 09:58:38.526587 29147 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 22.124468ms
>> I1013 09:58:38.526669 29147 replica.cpp:681] Persisted action at 2
>> I1013 09:58:38.528002 29145 replica.cpp:660] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1013 09:58:38.551810 29145 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 23.749842ms
>> I1013 09:58:38.551961 29145 leveldb.cpp:401] Deleting ~1 keys from
>> leveldb took 68370ns
>> I1013 09:58:38.551997 29145 replica.cpp:681] Persisted action at 2
>> I1013 09:58:38.552042 29145 replica.cpp:666] Replica learned TRUNCATE
>> action at position 2
>> I1013 09:58:38.555748 29117 scheduler.cpp:157] Version: 0.26.0
>> I1013 09:58:38.556823 29145 scheduler.cpp:240] New master detected at
>> master@172.17.5.161:57074
>> I1013 09:58:38.558246 29144 scheduler.cpp:302] Sending SUBSCRIBE call to
>> master@172.17.5.161:57074
>> I1013 09:58:38.561697 29143 process.cpp:3075] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1013 09:58:38.562072 29143 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.5.161:45381
>> I1013 09:58:38.562728 29143 master.cpp:1865] Received subscription
>> request for HTTP framework 'default'
>> I1013 09:58:38.562892 29143 master.cpp:1642] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1013 09:58:38.563436 29140 master.cpp:1957] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [ ]
>> I1013 09:58:38.564118 29140 hierarchical.hpp:515] Added framework
>> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
>> I1013 09:58:38.564157 29140 hierarchical.hpp:1328] No resources available
>> to allocate!
>> I1013 09:58:38.564244 29140 hierarchical.hpp:1423] No inverse offers to
>> send out!
>> I1013 09:58:38.564265 29140 hierarchical.hpp:1223] Performed allocation
>> for 0 slaves in 119906ns
>> I1013 09:58:38.564215 29141 master.hpp:1431] Sending heartbeat to
>> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
>> I1013 09:58:38.566124 29141 scheduler.cpp:461] Enqueuing event SUBSCRIBED
>> received from master@172.17.5.161:57074
>> I1013 09:58:38.566568 29141 scheduler.cpp:461] Enqueuing event HEARTBEAT
>> received from master@172.17.5.161:57074
>> I1013 09:58:38.567932 29151 master_maintenance_tests.cpp:179] Ignoring
>> HEARTBEAT event
>> I1013 09:58:38.568320 29151 scheduler.cpp:302] Sending REQUEST call to
>> master@172.17.5.161:57074
>> I1013 09:58:38.570888 29148 process.cpp:3075] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1013 09:58:38.571157 29148 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.5.161:45382
>> I1013 09:58:38.571723 29148 master.cpp:2618] Processing REQUEST call for
>> framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000 (default)
>> I1013 09:58:38.571964 29148 hierarchical.hpp:801] Received resource
>> request from framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
>> I1013 09:58:38.572737 29117 master.cpp:919] Master terminating
>> I1013 09:58:38.573541 29139 hierarchical.hpp:552] Removed framework
>> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
>> E1013 09:58:38.577641 29138 scheduler.cpp:435] End-Of-File received from
>> master. The master closed the event stream
>> [ OK ] ContentType/SchedulerTest.Request/1 (502 ms)
>> [----------] 22 tests from ContentType/SchedulerTest (15540 ms total)
>>
>> [----------] Global test environment tear-down
>> [==========] 807 tests from 110 test cases ran. (707196 ms total)
>> [ PASSED ] 806 tests.
>> [ FAILED ] 1 test, listed below:
>> [ FAILED ] ReservationEndpointsTest.AvailableResources
>>
>> 1 FAILED TEST
>> YOU HAVE 7 DISABLED TESTS
>>
>> make[4]: *** [check-local] Error 1
>> make[4]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
>> make[3]: *** [check-am] Error 2
>> make[3]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
>> make[2]: *** [check] Error 2
>> make[2]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
>> make[1]: *** [check-recursive] Error 1
>> make[1]: Leaving directory `/mesos/mesos-0.26.0/_build'
>> make: *** [distcheck] Error 1
>> + docker rmi mesos-1444727831-8911
>> Untagged: mesos-1444727831-8911:latest
>> Deleted: 84ca9f5fa2ebd0191688b2ffcf76296d0d991d75a9ae0a313ffea8956c39233b
>> Deleted: 26d8f638e61064921b2c9008e2ea232707a161101585a4ac60d173815a5b0176
>> Deleted: ab5864c334fdd1a5109558fcca2a93290ec3082f218757f60c56ab87a7c04d05
>> Deleted: 4d0c18b835dff04df5821b406448028a9492ad0e4597832f9441e30394b81ce0
>> Deleted: 3c6294ab4f00a8eb0c58c676cabebaf879134d32f685779c4fab08f3734cf693
>> Deleted: e2d06781179ea19561e24165e591b5353d68bed1677c8dea584a474c270cfc63
>> Deleted: 0896a0a04d6eafe255b59faf6a2983028dbed9e0a306d4584ea332133180e368
>> Deleted: 0fd565ae22f94bb38710569901763af3282dc00a886b404d0b2d40c18758ddf3
>> Deleted: aaca0877e4aa23770f37ca62ce596485fa8bde10905d61dfb4ecdfdf1ef8a4bf
>> Deleted: 8600cc9b3224a42d9d19bcfcb34537727b5c5ca8ab7a4925f793a6eb02475970
>> Deleted: 107c8af22de6519b0463cd13813b1455f2b341d42ad4edec2eb6bbffa2860397
>> Deleted: eecb9099b675455188f9dc0966dfa6b5f2d6a311983a87fad44647f86713acae
>> Deleted: 13edeb98704cf7aae557086b50dede5496d9663d85a30b6595f51df76559fa84
>> Build step 'Execute shell' marked build as failure
>>
>
>
Re: Build failed in Jenkins: Mesos » gcc,--verbose,ubuntu:14.04,docker||Hadoop #921
Posted by Benjamin Mahler <be...@gmail.com>.
+michael
Could you triage this test failure?
On Tue, Oct 13, 2015 at 2:58 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/921/changes
> >
>
> Changes:
>
> [mpark] Changed secret field in `Credential` from `bytes` to `string`
>
> ------------------------------------------
> [...truncated 137953 lines...]
> I1013 09:58:37.518443 29148 replica.cpp:681] Persisted action at 4
> I1013 09:58:37.518486 29148 replica.cpp:666] Replica learned TRUNCATE
> action at position 4
> I1013 09:58:37.520514 29117 slave.cpp:592] Slave terminating
> I1013 09:58:37.520606 29117 slave.cpp:2002] Asked to shut down framework
> ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000 by @0.0.0.0:0
> I1013 09:58:37.520650 29117 slave.cpp:2027] Shutting down framework
> ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
> I1013 09:58:37.520720 29117 slave.cpp:3839] Shutting down executor
> 'default' of framework ee09e948-8e7b-4f07-98b3-c9c87e28f3f1-0000
> [ OK ] ContentType/SchedulerTest.Message/1 (661 ms)
> [ RUN ] ContentType/SchedulerTest.Request/0
> Using temporary directory '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw'
> I1013 09:58:37.645978 29117 leveldb.cpp:176] Opened db in 117.641437ms
> I1013 09:58:37.696156 29117 leveldb.cpp:183] Compacted db in 50.096056ms
> I1013 09:58:37.696295 29117 leveldb.cpp:198] Created db iterator in 24234ns
> I1013 09:58:37.696311 29117 leveldb.cpp:204] Seeked to beginning of db in
> 2925ns
> I1013 09:58:37.696319 29117 leveldb.cpp:273] Iterated through 0 keys in
> the db in 230ns
> I1013 09:58:37.696372 29117 replica.cpp:746] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1013 09:58:37.696943 29142 recover.cpp:449] Starting replica recovery
> I1013 09:58:37.697202 29142 recover.cpp:475] Replica is in EMPTY status
> I1013 09:58:37.698290 29143 replica.cpp:642] Replica in EMPTY status
> received a broadcasted recover request from (9952)@172.17.5.161:57074
> I1013 09:58:37.698782 29151 recover.cpp:195] Received a recover response
> from a replica in EMPTY status
> I1013 09:58:37.699270 29139 recover.cpp:566] Updating replica status to
> STARTING
> I1013 09:58:37.700114 29143 master.cpp:376] Master
> 2cf0ec01-605e-47cd-8893-5fa5c02d778b (071521b41cca) started on
> 172.17.5.161:57074
> I1013 09:58:37.700139 29143 master.cpp:378] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/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.26.0/_inst/share/mesos/webui"
> --work_dir="/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/master"
> --zk_session_timeout="10secs"
> I1013 09:58:37.700453 29143 master.cpp:425] Master allowing
> unauthenticated frameworks to register
> I1013 09:58:37.700474 29143 master.cpp:428] Master only allowing
> authenticated slaves to register
> I1013 09:58:37.700487 29143 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/ContentType_SchedulerTest_Request_0_QTAyjw/credentials'
> I1013 09:58:37.700753 29143 master.cpp:467] Using default 'crammd5'
> authenticator
> I1013 09:58:37.700875 29143 master.cpp:504] Authorization enabled
> I1013 09:58:37.701099 29140 whitelist_watcher.cpp:79] No whitelist given
> I1013 09:58:37.701118 29139 hierarchical.hpp:468] Initialized hierarchical
> allocator process
> I1013 09:58:37.702304 29142 master.cpp:1603] The newly elected leader is
> master@172.17.5.161:57074 with id 2cf0ec01-605e-47cd-8893-5fa5c02d778b
> I1013 09:58:37.702337 29142 master.cpp:1616] Elected as the leading master!
> I1013 09:58:37.702352 29142 master.cpp:1376] Recovering from registrar
> I1013 09:58:37.702494 29146 registrar.cpp:309] Recovering registrar
> I1013 09:58:37.736212 29141 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 36.329384ms
> I1013 09:58:37.736285 29141 replica.cpp:323] Persisted replica status to
> STARTING
> I1013 09:58:37.736630 29145 recover.cpp:475] Replica is in STARTING status
> I1013 09:58:37.737884 29138 replica.cpp:642] Replica in STARTING status
> received a broadcasted recover request from (9953)@172.17.5.161:57074
> I1013 09:58:37.738332 29149 recover.cpp:195] Received a recover response
> from a replica in STARTING status
> I1013 09:58:37.738726 29141 recover.cpp:566] Updating replica status to
> VOTING
> I1013 09:58:37.763111 29136 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 24.221295ms
> I1013 09:58:37.763201 29136 replica.cpp:323] Persisted replica status to
> VOTING
> I1013 09:58:37.763413 29139 recover.cpp:580] Successfully joined the Paxos
> group
> I1013 09:58:37.763625 29139 recover.cpp:464] Recover process terminated
> I1013 09:58:37.764195 29151 log.cpp:661] Attempting to start the writer
> I1013 09:58:37.765425 29140 replica.cpp:478] Replica received implicit
> promise request from (9954)@172.17.5.161:57074 with proposal 1
> I1013 09:58:37.788241 29140 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 22.76316ms
> I1013 09:58:37.788431 29140 replica.cpp:345] Persisted promised to 1
> I1013 09:58:37.789913 29142 coordinator.cpp:231] Coordinator attemping to
> fill missing position
> I1013 09:58:37.791985 29140 replica.cpp:378] Replica received explicit
> promise request from (9955)@172.17.5.161:57074 for position 0 with
> proposal 2
> I1013 09:58:37.820113 29140 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 27.989977ms
> I1013 09:58:37.820233 29140 replica.cpp:681] Persisted action at 0
> I1013 09:58:37.822196 29143 replica.cpp:512] Replica received write
> request for position 0 from (9956)@172.17.5.161:57074
> I1013 09:58:37.822310 29143 leveldb.cpp:438] Reading position from leveldb
> took 58661ns
> I1013 09:58:37.852663 29143 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 30.257433ms
> I1013 09:58:37.852749 29143 replica.cpp:681] Persisted action at 0
> I1013 09:58:37.853713 29149 replica.cpp:660] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1013 09:58:37.890965 29149 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 37.192627ms
> I1013 09:58:37.891055 29149 replica.cpp:681] Persisted action at 0
> I1013 09:58:37.891088 29149 replica.cpp:666] Replica learned NOP action at
> position 0
> I1013 09:58:37.891880 29138 log.cpp:677] Writer started with ending
> position 0
> I1013 09:58:37.893005 29144 leveldb.cpp:438] Reading position from leveldb
> took 58276ns
> I1013 09:58:37.893924 29137 registrar.cpp:342] Successfully fetched the
> registry (0B) in 191.308032ms
> I1013 09:58:37.894063 29137 registrar.cpp:441] Applied 1 operations in
> 35330ns; attempting to update the 'registry'
> I1013 09:58:37.894876 29147 log.cpp:685] Attempting to append 176 bytes to
> the log
> I1013 09:58:37.894999 29139 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 1
> I1013 09:58:37.895704 29146 replica.cpp:512] Replica received write
> request for position 1 from (9957)@172.17.5.161:57074
> I1013 09:58:37.936381 29146 leveldb.cpp:343] Persisting action (195 bytes)
> to leveldb took 40.621032ms
> I1013 09:58:37.936467 29146 replica.cpp:681] Persisted action at 1
> I1013 09:58:37.937479 29136 replica.cpp:660] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1013 09:58:37.974557 29136 leveldb.cpp:343] Persisting action (197 bytes)
> to leveldb took 37.028107ms
> I1013 09:58:37.974647 29136 replica.cpp:681] Persisted action at 1
> I1013 09:58:37.974684 29136 replica.cpp:666] Replica learned APPEND action
> at position 1
> I1013 09:58:37.976876 29145 registrar.cpp:486] Successfully updated the
> 'registry' in 82.680064ms
> I1013 09:58:37.977061 29145 registrar.cpp:372] Successfully recovered
> registrar
> I1013 09:58:37.977252 29137 log.cpp:704] Attempting to truncate the log to
> 1
> I1013 09:58:37.977591 29137 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 2
> I1013 09:58:37.979133 29137 replica.cpp:512] Replica received write
> request for position 2 from (9958)@172.17.5.161:57074
> I1013 09:58:37.979919 29145 master.cpp:1413] Recovered 0 slaves from the
> Registry (137B) ; allowing 10mins for slaves to re-register
> I1013 09:58:38.016520 29137 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 37.215953ms
> I1013 09:58:38.016607 29137 replica.cpp:681] Persisted action at 2
> I1013 09:58:38.017614 29146 replica.cpp:660] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1013 09:58:38.053596 29146 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 35.926384ms
> I1013 09:58:38.053742 29146 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 64962ns
> I1013 09:58:38.053766 29146 replica.cpp:681] Persisted action at 2
> I1013 09:58:38.053799 29146 replica.cpp:666] Replica learned TRUNCATE
> action at position 2
> I1013 09:58:38.062036 29117 scheduler.cpp:157] Version: 0.26.0
> I1013 09:58:38.062861 29140 scheduler.cpp:240] New master detected at
> master@172.17.5.161:57074
> I1013 09:58:38.064096 29140 scheduler.cpp:302] Sending SUBSCRIBE call to
> master@172.17.5.161:57074
> I1013 09:58:38.066210 29139 process.cpp:3075] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1013 09:58:38.066473 29139 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.5.161:45379
> I1013 09:58:38.066685 29139 master.cpp:1865] Received subscription request
> for HTTP framework 'default'
> I1013 09:58:38.066777 29139 master.cpp:1642] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1013 09:58:38.067019 29139 master.cpp:1957] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I1013 09:58:38.067353 29145 hierarchical.hpp:515] Added framework
> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
> I1013 09:58:38.067387 29145 hierarchical.hpp:1328] No resources available
> to allocate!
> I1013 09:58:38.067409 29145 hierarchical.hpp:1423] No inverse offers to
> send out!
> I1013 09:58:38.067423 29139 master.hpp:1431] Sending heartbeat to
> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
> I1013 09:58:38.067425 29145 hierarchical.hpp:1223] Performed allocation
> for 0 slaves in 48435ns
> I1013 09:58:38.068274 29145 scheduler.cpp:461] Enqueuing event SUBSCRIBED
> received from master@172.17.5.161:57074
> I1013 09:58:38.068778 29145 scheduler.cpp:461] Enqueuing event HEARTBEAT
> received from master@172.17.5.161:57074
> I1013 09:58:38.069406 29149 master_maintenance_tests.cpp:179] Ignoring
> HEARTBEAT event
> I1013 09:58:38.069494 29145 scheduler.cpp:302] Sending REQUEST call to
> master@172.17.5.161:57074
> I1013 09:58:38.070850 29148 process.cpp:3075] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1013 09:58:38.071027 29148 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.5.161:45380
> I1013 09:58:38.071138 29148 master.cpp:2618] Processing REQUEST call for
> framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000 (default)
> I1013 09:58:38.071317 29146 hierarchical.hpp:801] Received resource
> request from framework 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
> I1013 09:58:38.071578 29147 master.cpp:919] Master terminating
> I1013 09:58:38.071739 29140 hierarchical.hpp:552] Removed framework
> 2cf0ec01-605e-47cd-8893-5fa5c02d778b-0000
> E1013 09:58:38.074120 29136 scheduler.cpp:435] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/0 (552 ms)
> [ RUN ] ContentType/SchedulerTest.Request/1
> Using temporary directory '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ'
> I1013 09:58:38.189395 29117 leveldb.cpp:176] Opened db in 109.310773ms
> I1013 09:58:38.206452 29117 leveldb.cpp:183] Compacted db in 16.987516ms
> I1013 09:58:38.206538 29117 leveldb.cpp:198] Created db iterator in 24050ns
> I1013 09:58:38.206555 29117 leveldb.cpp:204] Seeked to beginning of db in
> 2900ns
> I1013 09:58:38.206562 29117 leveldb.cpp:273] Iterated through 0 keys in
> the db in 205ns
> I1013 09:58:38.206611 29117 replica.cpp:746] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1013 09:58:38.207154 29140 recover.cpp:449] Starting replica recovery
> I1013 09:58:38.207386 29148 recover.cpp:475] Replica is in EMPTY status
> I1013 09:58:38.209626 29143 replica.cpp:642] Replica in EMPTY status
> received a broadcasted recover request from (9962)@172.17.5.161:57074
> I1013 09:58:38.209715 29143 master.cpp:376] Master
> f2c7f910-a186-48a6-bfcf-11403bd8fcd3 (071521b41cca) started on
> 172.17.5.161:57074
> I1013 09:58:38.209735 29143 master.cpp:378] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/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.26.0/_inst/share/mesos/webui"
> --work_dir="/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/master"
> --zk_session_timeout="10secs"
> I1013 09:58:38.210049 29143 master.cpp:425] Master allowing
> unauthenticated frameworks to register
> I1013 09:58:38.210054 29147 recover.cpp:195] Received a recover response
> from a replica in EMPTY status
> I1013 09:58:38.210069 29143 master.cpp:428] Master only allowing
> authenticated slaves to register
> I1013 09:58:38.210080 29143 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/ContentType_SchedulerTest_Request_1_12HnCJ/credentials'
> I1013 09:58:38.210433 29143 master.cpp:467] Using default 'crammd5'
> authenticator
> I1013 09:58:38.210556 29143 master.cpp:504] Authorization enabled
> I1013 09:58:38.210608 29139 recover.cpp:566] Updating replica status to
> STARTING
> I1013 09:58:38.210783 29137 whitelist_watcher.cpp:79] No whitelist given
> I1013 09:58:38.210793 29136 hierarchical.hpp:468] Initialized hierarchical
> allocator process
> I1013 09:58:38.211930 29148 master.cpp:1603] The newly elected leader is
> master@172.17.5.161:57074 with id f2c7f910-a186-48a6-bfcf-11403bd8fcd3
> I1013 09:58:38.211958 29148 master.cpp:1616] Elected as the leading master!
> I1013 09:58:38.211974 29148 master.cpp:1376] Recovering from registrar
> I1013 09:58:38.212134 29151 registrar.cpp:309] Recovering registrar
> I1013 09:58:38.254777 29137 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 43.732952ms
> I1013 09:58:38.254858 29137 replica.cpp:323] Persisted replica status to
> STARTING
> I1013 09:58:38.255199 29151 recover.cpp:475] Replica is in STARTING status
> I1013 09:58:38.257005 29144 replica.cpp:642] Replica in STARTING status
> received a broadcasted recover request from (9963)@172.17.5.161:57074
> I1013 09:58:38.257325 29147 recover.cpp:195] Received a recover response
> from a replica in STARTING status
> I1013 09:58:38.257869 29144 recover.cpp:566] Updating replica status to
> VOTING
> I1013 09:58:38.298324 29147 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 40.289075ms
> I1013 09:58:38.298395 29147 replica.cpp:323] Persisted replica status to
> VOTING
> I1013 09:58:38.298615 29144 recover.cpp:580] Successfully joined the Paxos
> group
> I1013 09:58:38.299027 29144 recover.cpp:464] Recover process terminated
> I1013 09:58:38.299420 29146 log.cpp:661] Attempting to start the writer
> I1013 09:58:38.300607 29149 replica.cpp:478] Replica received implicit
> promise request from (9964)@172.17.5.161:57074 with proposal 1
> I1013 09:58:38.340129 29149 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 39.4719ms
> I1013 09:58:38.340225 29149 replica.cpp:345] Persisted promised to 1
> I1013 09:58:38.341013 29138 coordinator.cpp:231] Coordinator attemping to
> fill missing position
> I1013 09:58:38.342344 29148 replica.cpp:378] Replica received explicit
> promise request from (9965)@172.17.5.161:57074 for position 0 with
> proposal 2
> I1013 09:58:38.381867 29148 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 39.460457ms
> I1013 09:58:38.381945 29148 replica.cpp:681] Persisted action at 0
> I1013 09:58:38.383513 29149 replica.cpp:512] Replica received write
> request for position 0 from (9966)@172.17.5.161:57074
> I1013 09:58:38.383710 29149 leveldb.cpp:438] Reading position from leveldb
> took 39304ns
> I1013 09:58:38.421689 29149 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 37.822366ms
> I1013 09:58:38.421775 29149 replica.cpp:681] Persisted action at 0
> I1013 09:58:38.422787 29149 replica.cpp:660] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1013 09:58:38.451143 29149 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 28.302809ms
> I1013 09:58:38.451225 29149 replica.cpp:681] Persisted action at 0
> I1013 09:58:38.451256 29149 replica.cpp:666] Replica learned NOP action at
> position 0
> I1013 09:58:38.452137 29144 log.cpp:677] Writer started with ending
> position 0
> I1013 09:58:38.453286 29143 leveldb.cpp:438] Reading position from leveldb
> took 50882ns
> I1013 09:58:38.454264 29143 registrar.cpp:342] Successfully fetched the
> registry (0B) in 241.997056ms
> I1013 09:58:38.454391 29143 registrar.cpp:441] Applied 1 operations in
> 26172ns; attempting to update the 'registry'
> I1013 09:58:38.455090 29150 log.cpp:685] Attempting to append 176 bytes to
> the log
> I1013 09:58:38.455220 29147 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 1
> I1013 09:58:38.455912 29136 replica.cpp:512] Replica received write
> request for position 1 from (9967)@172.17.5.161:57074
> I1013 09:58:38.476287 29136 leveldb.cpp:343] Persisting action (195 bytes)
> to leveldb took 20.327366ms
> I1013 09:58:38.476354 29136 replica.cpp:681] Persisted action at 1
> I1013 09:58:38.477073 29142 replica.cpp:660] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1013 09:58:38.501523 29142 leveldb.cpp:343] Persisting action (197 bytes)
> to leveldb took 24.401714ms
> I1013 09:58:38.501598 29142 replica.cpp:681] Persisted action at 1
> I1013 09:58:38.501629 29142 replica.cpp:666] Replica learned APPEND action
> at position 1
> I1013 09:58:38.503021 29136 registrar.cpp:486] Successfully updated the
> 'registry' in 48.561152ms
> I1013 09:58:38.503144 29136 registrar.cpp:372] Successfully recovered
> registrar
> I1013 09:58:38.503325 29149 log.cpp:704] Attempting to truncate the log to
> 1
> I1013 09:58:38.503463 29141 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 2
> I1013 09:58:38.503535 29142 master.cpp:1413] Recovered 0 slaves from the
> Registry (137B) ; allowing 10mins for slaves to re-register
> I1013 09:58:38.504396 29147 replica.cpp:512] Replica received write
> request for position 2 from (9968)@172.17.5.161:57074
> I1013 09:58:38.526587 29147 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 22.124468ms
> I1013 09:58:38.526669 29147 replica.cpp:681] Persisted action at 2
> I1013 09:58:38.528002 29145 replica.cpp:660] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1013 09:58:38.551810 29145 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 23.749842ms
> I1013 09:58:38.551961 29145 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 68370ns
> I1013 09:58:38.551997 29145 replica.cpp:681] Persisted action at 2
> I1013 09:58:38.552042 29145 replica.cpp:666] Replica learned TRUNCATE
> action at position 2
> I1013 09:58:38.555748 29117 scheduler.cpp:157] Version: 0.26.0
> I1013 09:58:38.556823 29145 scheduler.cpp:240] New master detected at
> master@172.17.5.161:57074
> I1013 09:58:38.558246 29144 scheduler.cpp:302] Sending SUBSCRIBE call to
> master@172.17.5.161:57074
> I1013 09:58:38.561697 29143 process.cpp:3075] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1013 09:58:38.562072 29143 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.5.161:45381
> I1013 09:58:38.562728 29143 master.cpp:1865] Received subscription request
> for HTTP framework 'default'
> I1013 09:58:38.562892 29143 master.cpp:1642] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1013 09:58:38.563436 29140 master.cpp:1957] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I1013 09:58:38.564118 29140 hierarchical.hpp:515] Added framework
> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
> I1013 09:58:38.564157 29140 hierarchical.hpp:1328] No resources available
> to allocate!
> I1013 09:58:38.564244 29140 hierarchical.hpp:1423] No inverse offers to
> send out!
> I1013 09:58:38.564265 29140 hierarchical.hpp:1223] Performed allocation
> for 0 slaves in 119906ns
> I1013 09:58:38.564215 29141 master.hpp:1431] Sending heartbeat to
> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
> I1013 09:58:38.566124 29141 scheduler.cpp:461] Enqueuing event SUBSCRIBED
> received from master@172.17.5.161:57074
> I1013 09:58:38.566568 29141 scheduler.cpp:461] Enqueuing event HEARTBEAT
> received from master@172.17.5.161:57074
> I1013 09:58:38.567932 29151 master_maintenance_tests.cpp:179] Ignoring
> HEARTBEAT event
> I1013 09:58:38.568320 29151 scheduler.cpp:302] Sending REQUEST call to
> master@172.17.5.161:57074
> I1013 09:58:38.570888 29148 process.cpp:3075] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1013 09:58:38.571157 29148 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.5.161:45382
> I1013 09:58:38.571723 29148 master.cpp:2618] Processing REQUEST call for
> framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000 (default)
> I1013 09:58:38.571964 29148 hierarchical.hpp:801] Received resource
> request from framework f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
> I1013 09:58:38.572737 29117 master.cpp:919] Master terminating
> I1013 09:58:38.573541 29139 hierarchical.hpp:552] Removed framework
> f2c7f910-a186-48a6-bfcf-11403bd8fcd3-0000
> E1013 09:58:38.577641 29138 scheduler.cpp:435] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/1 (502 ms)
> [----------] 22 tests from ContentType/SchedulerTest (15540 ms total)
>
> [----------] Global test environment tear-down
> [==========] 807 tests from 110 test cases ran. (707196 ms total)
> [ PASSED ] 806 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] ReservationEndpointsTest.AvailableResources
>
> 1 FAILED TEST
> YOU HAVE 7 DISABLED TESTS
>
> make[4]: *** [check-local] Error 1
> make[4]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
> make[3]: *** [check-am] Error 2
> make[3]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
> make[2]: *** [check] Error 2
> make[2]: Leaving directory `/mesos/mesos-0.26.0/_build/src'
> make[1]: *** [check-recursive] Error 1
> make[1]: Leaving directory `/mesos/mesos-0.26.0/_build'
> make: *** [distcheck] Error 1
> + docker rmi mesos-1444727831-8911
> Untagged: mesos-1444727831-8911:latest
> Deleted: 84ca9f5fa2ebd0191688b2ffcf76296d0d991d75a9ae0a313ffea8956c39233b
> Deleted: 26d8f638e61064921b2c9008e2ea232707a161101585a4ac60d173815a5b0176
> Deleted: ab5864c334fdd1a5109558fcca2a93290ec3082f218757f60c56ab87a7c04d05
> Deleted: 4d0c18b835dff04df5821b406448028a9492ad0e4597832f9441e30394b81ce0
> Deleted: 3c6294ab4f00a8eb0c58c676cabebaf879134d32f685779c4fab08f3734cf693
> Deleted: e2d06781179ea19561e24165e591b5353d68bed1677c8dea584a474c270cfc63
> Deleted: 0896a0a04d6eafe255b59faf6a2983028dbed9e0a306d4584ea332133180e368
> Deleted: 0fd565ae22f94bb38710569901763af3282dc00a886b404d0b2d40c18758ddf3
> Deleted: aaca0877e4aa23770f37ca62ce596485fa8bde10905d61dfb4ecdfdf1ef8a4bf
> Deleted: 8600cc9b3224a42d9d19bcfcb34537727b5c5ca8ab7a4925f793a6eb02475970
> Deleted: 107c8af22de6519b0463cd13813b1455f2b341d42ad4edec2eb6bbffa2860397
> Deleted: eecb9099b675455188f9dc0966dfa6b5f2d6a311983a87fad44647f86713acae
> Deleted: 13edeb98704cf7aae557086b50dede5496d9663d85a30b6595f51df76559fa84
> Build step 'Execute shell' marked build as failure
>