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/12/09 08:17:38 UTC
Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1335
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1335/changes>
Changes:
[mpark] Fixed flakiness in `ReservationTest.ACLMultipleOperations`.
[mpark] Shortened `allocation_interval` from 50ms to 5ms in `ReservationTest`s
------------------------------------------
[...truncated 148823 lines...]
I1209 07:17:35.789157 31387 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_7xP429/slaves/eab71b8b-fe49-4d30-8ff5-5654973e8524-S0/frameworks/eab71b8b-fe49-4d30-8ff5-5654973e8524-0000/executors/default/runs/7dfc8e18-60e3-44b1-925d-b447fe3bc199' for gc 6.99999086809185days in the future
I1209 07:17:35.789207 31381 slave.cpp:3947] Cleaning up framework eab71b8b-fe49-4d30-8ff5-5654973e8524-0000
I1209 07:17:35.789333 31387 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_7xP429/slaves/eab71b8b-fe49-4d30-8ff5-5654973e8524-S0/frameworks/eab71b8b-fe49-4d30-8ff5-5654973e8524-0000/executors/default' for gc 6.9999908662963days in the future
I1209 07:17:35.789449 31381 status_update_manager.cpp:282] Closing status update streams for framework eab71b8b-fe49-4d30-8ff5-5654973e8524-0000
I1209 07:17:35.789511 31381 status_update_manager.cpp:528] Cleaning up status update stream for task b910e3f7-2a1f-4892-b0e4-f30fa667b764 of framework eab71b8b-fe49-4d30-8ff5-5654973e8524-0000
I1209 07:17:35.789649 31387 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_7xP429/slaves/eab71b8b-fe49-4d30-8ff5-5654973e8524-S0/frameworks/eab71b8b-fe49-4d30-8ff5-5654973e8524-0000' for gc 6.9999908644days in the future
[ OK ] ContentType/SchedulerTest.Message/1 (108 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I1209 07:17:35.795996 31353 leveldb.cpp:174] Opened db in 2.161684ms
I1209 07:17:35.796588 31353 leveldb.cpp:181] Compacted db in 559048ns
I1209 07:17:35.796634 31353 leveldb.cpp:196] Created db iterator in 20870ns
I1209 07:17:35.796659 31353 leveldb.cpp:202] Seeked to beginning of db in 2284ns
I1209 07:17:35.796674 31353 leveldb.cpp:271] Iterated through 0 keys in the db in 377ns
I1209 07:17:35.796726 31353 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1209 07:17:35.797196 31381 recover.cpp:447] Starting replica recovery
I1209 07:17:35.797442 31381 recover.cpp:473] Replica is in EMPTY status
I1209 07:17:35.798462 31382 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11478)@172.17.0.1:53832
2015-12-09 07:17:35,798:31353(0x7f2015720700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:46197] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1209 07:17:35.799000 31383 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1209 07:17:35.799862 31375 master.cpp:365] Master 994df8ff-1022-4d93-9027-527c65b08f25 (2b2dd4548913) started on 172.17.0.1:53832
I1209 07:17:35.799887 31375 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/VjT8vV/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/VjT8vV/master" --zk_session_timeout="10secs"
I1209 07:17:35.800199 31375 master.cpp:414] Master allowing unauthenticated frameworks to register
I1209 07:17:35.800210 31375 master.cpp:417] Master only allowing authenticated slaves to register
I1209 07:17:35.800216 31375 credentials.hpp:35] Loading credentials for authentication from '/tmp/VjT8vV/credentials'
I1209 07:17:35.800448 31375 master.cpp:456] Using default 'crammd5' authenticator
I1209 07:17:35.800623 31373 recover.cpp:564] Updating replica status to STARTING
I1209 07:17:35.800756 31375 master.cpp:493] Authorization enabled
I1209 07:17:35.801147 31373 hierarchical.cpp:163] Initialized hierarchical allocator process
I1209 07:17:35.801226 31372 whitelist_watcher.cpp:77] No whitelist given
I1209 07:17:35.801439 31387 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 463354ns
I1209 07:17:35.801481 31387 replica.cpp:321] Persisted replica status to STARTING
I1209 07:17:35.801982 31382 recover.cpp:473] Replica is in STARTING status
I1209 07:17:35.803133 31378 master.cpp:1637] The newly elected leader is master@172.17.0.1:53832 with id 994df8ff-1022-4d93-9027-527c65b08f25
I1209 07:17:35.803170 31378 master.cpp:1650] Elected as the leading master!
I1209 07:17:35.803447 31378 master.cpp:1395] Recovering from registrar
I1209 07:17:35.803614 31385 registrar.cpp:307] Recovering registrar
I1209 07:17:35.803406 31379 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11479)@172.17.0.1:53832
I1209 07:17:35.804280 31372 recover.cpp:193] Received a recover response from a replica in STARTING status
I1209 07:17:35.805210 31385 recover.cpp:564] Updating replica status to VOTING
I1209 07:17:35.805797 31379 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 383009ns
I1209 07:17:35.805845 31379 replica.cpp:321] Persisted replica status to VOTING
I1209 07:17:35.805994 31379 recover.cpp:578] Successfully joined the Paxos group
I1209 07:17:35.806196 31379 recover.cpp:462] Recover process terminated
I1209 07:17:35.806870 31379 log.cpp:659] Attempting to start the writer
I1209 07:17:35.808056 31372 replica.cpp:494] Replica received implicit promise request from (11480)@172.17.0.1:53832 with proposal 1
I1209 07:17:35.808462 31372 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 370142ns
I1209 07:17:35.808488 31372 replica.cpp:343] Persisted promised to 1
I1209 07:17:35.809142 31385 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1209 07:17:35.810391 31376 replica.cpp:389] Replica received explicit promise request from (11481)@172.17.0.1:53832 for position 0 with proposal 2
I1209 07:17:35.810752 31376 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 321399ns
I1209 07:17:35.810778 31376 replica.cpp:713] Persisted action at 0
I1209 07:17:35.811745 31379 replica.cpp:538] Replica received write request for position 0 from (11482)@172.17.0.1:53832
I1209 07:17:35.811852 31379 leveldb.cpp:436] Reading position from leveldb took 55239ns
I1209 07:17:35.812211 31379 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 300708ns
I1209 07:17:35.812232 31379 replica.cpp:713] Persisted action at 0
I1209 07:17:35.812747 31380 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1209 07:17:35.813194 31380 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 339370ns
I1209 07:17:35.813217 31380 replica.cpp:713] Persisted action at 0
I1209 07:17:35.813232 31380 replica.cpp:698] Replica learned NOP action at position 0
I1209 07:17:35.813700 31377 log.cpp:675] Writer started with ending position 0
I1209 07:17:35.814745 31384 leveldb.cpp:436] Reading position from leveldb took 29651ns
I1209 07:17:35.815677 31373 registrar.cpp:340] Successfully fetched the registry (0B) in 12.009728ms
I1209 07:17:35.815860 31373 registrar.cpp:439] Applied 1 operations in 38402ns; attempting to update the 'registry'
I1209 07:17:35.816527 31378 log.cpp:683] Attempting to append 170 bytes to the log
I1209 07:17:35.816643 31386 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1209 07:17:35.817399 31387 replica.cpp:538] Replica received write request for position 1 from (11483)@172.17.0.1:53832
I1209 07:17:35.817755 31387 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 318288ns
I1209 07:17:35.817780 31387 replica.cpp:713] Persisted action at 1
I1209 07:17:35.818346 31381 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1209 07:17:35.818647 31381 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 275629ns
I1209 07:17:35.818670 31381 replica.cpp:713] Persisted action at 1
I1209 07:17:35.818691 31381 replica.cpp:698] Replica learned APPEND action at position 1
I1209 07:17:35.819546 31384 registrar.cpp:484] Successfully updated the 'registry' in 3.62112ms
I1209 07:17:35.819671 31384 registrar.cpp:370] Successfully recovered registrar
I1209 07:17:35.819875 31378 log.cpp:702] Attempting to truncate the log to 1
I1209 07:17:35.820199 31375 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1209 07:17:35.820415 31386 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1209 07:17:35.820468 31372 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1209 07:17:35.821251 31384 replica.cpp:538] Replica received write request for position 2 from (11484)@172.17.0.1:53832
I1209 07:17:35.821621 31384 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 330490ns
I1209 07:17:35.821647 31384 replica.cpp:713] Persisted action at 2
I1209 07:17:35.822217 31377 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1209 07:17:35.822558 31377 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 306430ns
I1209 07:17:35.822608 31377 leveldb.cpp:399] Deleting ~1 keys from leveldb took 26890ns
I1209 07:17:35.822635 31377 replica.cpp:713] Persisted action at 2
I1209 07:17:35.822655 31377 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1209 07:17:35.831395 31353 scheduler.cpp:154] Version: 0.27.0
I1209 07:17:35.832114 31382 scheduler.cpp:236] New master detected at master@172.17.0.1:53832
I1209 07:17:35.833128 31377 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.1:53832
I1209 07:17:35.834995 31377 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 07:17:35.835062 31377 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:44395
I1209 07:17:35.835237 31377 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1209 07:17:35.835306 31377 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1209 07:17:35.835559 31377 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1209 07:17:35.836097 31376 hierarchical.cpp:267] Added framework 994df8ff-1022-4d93-9027-527c65b08f25-0000
I1209 07:17:35.836177 31376 hierarchical.cpp:1317] No resources available to allocate!
I1209 07:17:35.836218 31376 hierarchical.cpp:1410] No inverse offers to send out!
I1209 07:17:35.836247 31376 hierarchical.cpp:1063] Performed allocation for 0 slaves in 121155ns
I1209 07:17:35.836462 31376 master.hpp:1583] Sending heartbeat to 994df8ff-1022-4d93-9027-527c65b08f25-0000
I1209 07:17:35.837402 31384 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.1:53832
I1209 07:17:35.837854 31384 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.1:53832
I1209 07:17:35.838457 31386 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I1209 07:17:35.838852 31381 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.1:53832
I1209 07:17:35.840318 31381 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 07:17:35.840379 31381 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:44396
I1209 07:17:35.840487 31381 master.cpp:2646] Processing REQUEST call for framework 994df8ff-1022-4d93-9027-527c65b08f25-0000 (default)
I1209 07:17:35.840713 31381 hierarchical.cpp:562] Received resource request from framework 994df8ff-1022-4d93-9027-527c65b08f25-0000
I1209 07:17:35.841157 31375 master.cpp:938] Master terminating
I1209 07:17:35.841423 31384 hierarchical.cpp:308] Removed framework 994df8ff-1022-4d93-9027-527c65b08f25-0000
E1209 07:17:35.843653 31386 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (60 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I1209 07:17:35.856709 31353 leveldb.cpp:174] Opened db in 2.596906ms
I1209 07:17:35.857661 31353 leveldb.cpp:181] Compacted db in 783233ns
I1209 07:17:35.857728 31353 leveldb.cpp:196] Created db iterator in 24750ns
I1209 07:17:35.857812 31353 leveldb.cpp:202] Seeked to beginning of db in 2605ns
I1209 07:17:35.857928 31353 leveldb.cpp:271] Iterated through 0 keys in the db in 468ns
I1209 07:17:35.857996 31353 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1209 07:17:35.858522 31387 recover.cpp:447] Starting replica recovery
I1209 07:17:35.858906 31376 recover.cpp:473] Replica is in EMPTY status
I1209 07:17:35.860553 31386 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11489)@172.17.0.1:53832
I1209 07:17:35.860997 31378 master.cpp:365] Master 986e1506-ca53-42bb-9c34-c6694c474be8 (2b2dd4548913) started on 172.17.0.1:53832
I1209 07:17:35.861116 31378 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/jQXAVQ/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/jQXAVQ/master" --zk_session_timeout="10secs"
I1209 07:17:35.861479 31378 master.cpp:414] Master allowing unauthenticated frameworks to register
I1209 07:17:35.861500 31378 master.cpp:417] Master only allowing authenticated slaves to register
I1209 07:17:35.861513 31378 credentials.hpp:35] Loading credentials for authentication from '/tmp/jQXAVQ/credentials'
I1209 07:17:35.861840 31378 master.cpp:456] Using default 'crammd5' authenticator
I1209 07:17:35.862402 31381 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1209 07:17:35.862685 31378 master.cpp:493] Authorization enabled
I1209 07:17:35.862968 31382 hierarchical.cpp:163] Initialized hierarchical allocator process
I1209 07:17:35.863029 31381 recover.cpp:564] Updating replica status to STARTING
I1209 07:17:35.863039 31382 whitelist_watcher.cpp:77] No whitelist given
I1209 07:17:35.863776 31382 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 492740ns
I1209 07:17:35.863986 31382 replica.cpp:321] Persisted replica status to STARTING
I1209 07:17:35.864482 31382 recover.cpp:473] Replica is in STARTING status
I1209 07:17:35.864969 31374 master.cpp:1637] The newly elected leader is master@172.17.0.1:53832 with id 986e1506-ca53-42bb-9c34-c6694c474be8
I1209 07:17:35.865066 31374 master.cpp:1650] Elected as the leading master!
I1209 07:17:35.865171 31374 master.cpp:1395] Recovering from registrar
I1209 07:17:35.865433 31381 registrar.cpp:307] Recovering registrar
I1209 07:17:35.866125 31381 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11490)@172.17.0.1:53832
I1209 07:17:35.866865 31382 recover.cpp:193] Received a recover response from a replica in STARTING status
I1209 07:17:35.867234 31381 recover.cpp:564] Updating replica status to VOTING
I1209 07:17:35.867841 31382 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 385628ns
I1209 07:17:35.867866 31382 replica.cpp:321] Persisted replica status to VOTING
I1209 07:17:35.867976 31382 recover.cpp:578] Successfully joined the Paxos group
I1209 07:17:35.868206 31382 recover.cpp:462] Recover process terminated
I1209 07:17:35.868654 31383 log.cpp:659] Attempting to start the writer
I1209 07:17:35.870008 31380 replica.cpp:494] Replica received implicit promise request from (11491)@172.17.0.1:53832 with proposal 1
I1209 07:17:35.870406 31380 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 364603ns
I1209 07:17:35.870429 31380 replica.cpp:343] Persisted promised to 1
I1209 07:17:35.871081 31376 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1209 07:17:35.872159 31375 replica.cpp:389] Replica received explicit promise request from (11492)@172.17.0.1:53832 for position 0 with proposal 2
I1209 07:17:35.872520 31375 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 316946ns
I1209 07:17:35.872542 31375 replica.cpp:713] Persisted action at 0
I1209 07:17:35.873661 31373 replica.cpp:538] Replica received write request for position 0 from (11493)@172.17.0.1:53832
I1209 07:17:35.873721 31373 leveldb.cpp:436] Reading position from leveldb took 28979ns
I1209 07:17:35.874177 31373 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 295431ns
I1209 07:17:35.874202 31373 replica.cpp:713] Persisted action at 0
I1209 07:17:35.874716 31372 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1209 07:17:35.874977 31372 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 227294ns
I1209 07:17:35.875007 31372 replica.cpp:713] Persisted action at 0
I1209 07:17:35.875030 31372 replica.cpp:698] Replica learned NOP action at position 0
I1209 07:17:35.875563 31387 log.cpp:675] Writer started with ending position 0
I1209 07:17:35.876660 31381 leveldb.cpp:436] Reading position from leveldb took 26102ns
I1209 07:17:35.877512 31381 registrar.cpp:340] Successfully fetched the registry (0B) in 11.879168ms
I1209 07:17:35.877638 31381 registrar.cpp:439] Applied 1 operations in 31381ns; attempting to update the 'registry'
I1209 07:17:35.878314 31385 log.cpp:683] Attempting to append 170 bytes to the log
I1209 07:17:35.878422 31382 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1209 07:17:35.879218 31372 replica.cpp:538] Replica received write request for position 1 from (11494)@172.17.0.1:53832
I1209 07:17:35.879536 31372 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 285026ns
I1209 07:17:35.879559 31372 replica.cpp:713] Persisted action at 1
I1209 07:17:35.880161 31377 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1209 07:17:35.880468 31377 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 276393ns
I1209 07:17:35.880491 31377 replica.cpp:713] Persisted action at 1
I1209 07:17:35.880506 31377 replica.cpp:698] Replica learned APPEND action at position 1
I1209 07:17:35.881417 31381 registrar.cpp:484] Successfully updated the 'registry' in 3.707648ms
I1209 07:17:35.881564 31381 registrar.cpp:370] Successfully recovered registrar
I1209 07:17:35.881597 31375 log.cpp:702] Attempting to truncate the log to 1
I1209 07:17:35.881762 31380 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1209 07:17:35.882107 31375 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1209 07:17:35.882138 31381 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1209 07:17:35.882700 31382 replica.cpp:538] Replica received write request for position 2 from (11495)@172.17.0.1:53832
I1209 07:17:35.883074 31382 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 340079ns
I1209 07:17:35.883096 31382 replica.cpp:713] Persisted action at 2
I1209 07:17:35.883690 31374 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1209 07:17:35.883992 31374 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 276660ns
I1209 07:17:35.884047 31374 leveldb.cpp:399] Deleting ~1 keys from leveldb took 30668ns
I1209 07:17:35.884157 31374 replica.cpp:713] Persisted action at 2
I1209 07:17:35.884188 31374 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1209 07:17:35.893061 31353 scheduler.cpp:154] Version: 0.27.0
I1209 07:17:35.893769 31385 scheduler.cpp:236] New master detected at master@172.17.0.1:53832
I1209 07:17:35.894755 31382 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.1:53832
I1209 07:17:35.897068 31387 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 07:17:35.897187 31387 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:44397
I1209 07:17:35.897512 31387 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1209 07:17:35.897593 31387 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1209 07:17:35.898185 31387 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1209 07:17:35.898775 31387 hierarchical.cpp:267] Added framework 986e1506-ca53-42bb-9c34-c6694c474be8-0000
I1209 07:17:35.898860 31381 master.hpp:1583] Sending heartbeat to 986e1506-ca53-42bb-9c34-c6694c474be8-0000
I1209 07:17:35.899407 31387 hierarchical.cpp:1317] No resources available to allocate!
I1209 07:17:35.899452 31387 hierarchical.cpp:1410] No inverse offers to send out!
I1209 07:17:35.899488 31387 hierarchical.cpp:1063] Performed allocation for 0 slaves in 689265ns
I1209 07:17:35.899766 31384 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.1:53832
I1209 07:17:35.900192 31384 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.1:53832
I1209 07:17:35.900919 31380 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I1209 07:17:35.900959 31384 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.1:53832
I1209 07:17:35.902495 31384 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 07:17:35.902623 31384 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:44398
I1209 07:17:35.902860 31384 master.cpp:2646] Processing REQUEST call for framework 986e1506-ca53-42bb-9c34-c6694c474be8-0000 (default)
I1209 07:17:35.903012 31381 hierarchical.cpp:562] Received resource request from framework 986e1506-ca53-42bb-9c34-c6694c474be8-0000
I1209 07:17:35.903301 31384 master.cpp:938] Master terminating
I1209 07:17:35.903569 31379 hierarchical.cpp:308] Removed framework 986e1506-ca53-42bb-9c34-c6694c474be8-0000
E1209 07:17:35.904284 31374 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (56 ms)
[----------] 22 tests from ContentType/SchedulerTest (4491 ms total)
[----------] Global test environment tear-down
[==========] 882 tests from 116 test cases ran. (356657 ms total)
[ PASSED ] 881 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] HealthCheckTest.CheckCommandTimeout
1 FAILED TEST
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-1449643816-32118
Untagged: mesos-1449643816-32118:latest
Deleted: d7068d0279a06e0636a427a87fcbd6bd260ec455294902ad5a9f61aa285463e0
Deleted: 9f12e10f5570d7b7e4e99d45c12703900cb15e1b23c13f025eebce73829973cc
Deleted: 923a31bb515c148de99ba481879c6c38ce15ab8e8079d87097fa3ee630b6fc21
Deleted: a3c4926061355f3ac957cd5acc12385f6a15bb609e1980e576e011a7f0fa0d83
Deleted: 69bc8c85ba2886830d9964f1e26c53a3909f9bc9f63ea474aed61b02c2553be4
Deleted: 8671a252c4cd96a3b4bdd706aa11d6ed445c55c0726edffc48451e3631f1cd96
Deleted: eb46d49b7846787f69708b64e904528dd295d898ac00772a745c1bd580f09ee6
Deleted: 444375174a3954d28f9e7aa5878dfbc93669efa8fc92c97da9194a2a366f6302
Deleted: baf643eaf7e1faf2bf74f440bc5465c9a1fd46eb6eb41b5c81235ebac8d2952f
Deleted: 7c3e350cb1796d53f0f25cd47bfa6b77d96f8777e4266476f0141dc81f5e7512
Deleted: 3e1e0eff956d5e9db189d676d43bde456f5a8c2863a37417c5d67402401dd751
Deleted: 1bf963b4c30f81b771a517d48adefa38d8b0756c7aa25d97030b31852d82dc4e
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos » gcc,--verbose,centos:7,docker||Hadoop #1338
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1338/changes>
Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1337
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1337/>
------------------------------------------
Started by upstream project "Mesos" build number 1337
originally caused by:
Started by an SCM change
[EnvInject] - Loading node environment variables.
Building remotely on H6 (Mapreduce Falcon Hadoop Pig Zookeeper Tez Hdfs) in workspace <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/ws/>
Cloning the remote Git repository
Using shallow clone
Cloning repository https://git-wip-us.apache.org/repos/asf/mesos.git
> git init <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/ws/> # timeout=10
Fetching upstream changes from https://git-wip-us.apache.org/repos/asf/mesos.git
> git --version # timeout=10
> git -c core.askpass=true fetch --tags --progress https://git-wip-us.apache.org/repos/asf/mesos.git +refs/heads/*:refs/remotes/origin/* --depth=1 # timeout=60
> git config remote.origin.url https://git-wip-us.apache.org/repos/asf/mesos.git # timeout=10
> git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10
> git config remote.origin.url https://git-wip-us.apache.org/repos/asf/mesos.git # timeout=10
Fetching upstream changes from https://git-wip-us.apache.org/repos/asf/mesos.git
> git -c core.askpass=true fetch --tags --progress https://git-wip-us.apache.org/repos/asf/mesos.git +refs/heads/*:refs/remotes/origin/* # timeout=60
Checking out Revision 7cec89b5de76f9f6ff537cec39c8eb18ad75349b (origin/master)
> git config core.sparsecheckout # timeout=10
> git checkout -f 7cec89b5de76f9f6ff537cec39c8eb18ad75349b
FATAL: Could not checkout 7cec89b5de76f9f6ff537cec39c8eb18ad75349b
hudson.plugins.git.GitException: Could not checkout 7cec89b5de76f9f6ff537cec39c8eb18ad75349b
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl$8.execute(CliGitAPIImpl.java:1907)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:152)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:145)
at hudson.remoting.UserRequest.perform(UserRequest.java:121)
at hudson.remoting.UserRequest.perform(UserRequest.java:49)
at hudson.remoting.Request$2.run(Request.java:326)
at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at ......remote call to H6(Native Method)
at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1413)
at hudson.remoting.UserResponse.retrieve(UserRequest.java:221)
at hudson.remoting.Channel.call(Channel.java:778)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.execute(RemoteGitImpl.java:145)
at sun.reflect.GeneratedMethodAccessor440.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.invoke(RemoteGitImpl.java:131)
at com.sun.proxy.$Proxy137.execute(Unknown Source)
at hudson.plugins.git.GitSCM.checkout(GitSCM.java:1060)
at hudson.scm.SCM.checkout(SCM.java:484)
at hudson.model.AbstractProject.checkout(AbstractProject.java:1274)
at hudson.model.AbstractBuild$AbstractBuildExecution.defaultCheckout(AbstractBuild.java:609)
at jenkins.scm.SCMCheckoutStrategy.checkout(SCMCheckoutStrategy.java:86)
at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:531)
at hudson.model.Run.execute(Run.java:1738)
at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
at hudson.model.ResourceController.execute(ResourceController.java:98)
at hudson.model.Executor.run(Executor.java:381)
Caused by: hudson.plugins.git.GitException: Command "git checkout -f 7cec89b5de76f9f6ff537cec39c8eb18ad75349b" returned status code 128:
stdout:
stderr: fatal: reference is not a tree: 7cec89b5de76f9f6ff537cec39c8eb18ad75349b
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1640)
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.access$500(CliGitAPIImpl.java:62)
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl$8.execute(CliGitAPIImpl.java:1899)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:152)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:145)
at hudson.remoting.UserRequest.perform(UserRequest.java:121)
at hudson.remoting.UserRequest.perform(UserRequest.java:49)
at hudson.remoting.Request$2.run(Request.java:326)
at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Re: Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1336
Posted by Benjamin Mahler <be...@gmail.com>.
https://issues.apache.org/jira/browse/MESOS-4024
On Wed, Dec 9, 2015 at 1:32 AM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1336/changes
> >
>
> Changes:
>
> [tnachen] Add mesos provisioner doc.
>
> ------------------------------------------
> [...truncated 153346 lines...]
> I1209 09:32:06.646441 31386 slave.cpp:3859] Cleaning up executor 'default'
> of framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000 at executor(135)@
> 172.17.0.1:36768
> I1209 09:32:06.646623 31383 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000/executors/default/runs/995547a3-580a-4852-a3de-9c947f10e9b6'
> for gc 6.99999251674667days in the future
> I1209 09:32:06.646757 31386 slave.cpp:3947] Cleaning up framework
> 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
> I1209 09:32:06.646775 31383 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000/executors/default'
> for gc 6.99999251503407days in the future
> I1209 09:32:06.646872 31378 status_update_manager.cpp:282] Closing status
> update streams for framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
> I1209 09:32:06.646934 31378 status_update_manager.cpp:528] Cleaning up
> status update stream for task 5bcaf46a-6505-47fc-bb3c-b47682ea632e of
> framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
> I1209 09:32:06.646956 31389 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000'
> for gc 6.99999251305481days in the future
> [ OK ] ContentType/SchedulerTest.Message/1 (626 ms)
> [ RUN ] ContentType/SchedulerTest.Request/0
> I1209 09:32:06.764993 31357 leveldb.cpp:174] Opened db in 113.871537ms
> I1209 09:32:06.816138 31357 leveldb.cpp:181] Compacted db in 51.06532ms
> I1209 09:32:06.816267 31357 leveldb.cpp:196] Created db iterator in 30876ns
> I1209 09:32:06.816283 31357 leveldb.cpp:202] Seeked to beginning of db in
> 4150ns
> I1209 09:32:06.816292 31357 leveldb.cpp:271] Iterated through 0 keys in
> the db in 251ns
> I1209 09:32:06.816346 31357 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1209 09:32:06.817158 31391 recover.cpp:447] Starting replica recovery
> I1209 09:32:06.817488 31391 recover.cpp:473] Replica is in EMPTY status
> I1209 09:32:06.818835 31376 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11515)@172.17.0.1:36768
> I1209 09:32:06.819315 31387 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1209 09:32:06.819808 31382 recover.cpp:564] Updating replica status to
> STARTING
> I1209 09:32:06.820646 31381 master.cpp:365] Master
> 8915e203-6fb7-47de-9efa-cbd35e80f323 (83469567f7e5) started on
> 172.17.0.1:36768
> I1209 09:32:06.820677 31381 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/EXBunl/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/EXBunl/master" --zk_session_timeout="10secs"
> I1209 09:32:06.821024 31381 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1209 09:32:06.821053 31381 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1209 09:32:06.821072 31381 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/EXBunl/credentials'
> I1209 09:32:06.821445 31381 master.cpp:456] Using default 'crammd5'
> authenticator
> I1209 09:32:06.821604 31381 master.cpp:493] Authorization enabled
> I1209 09:32:06.821856 31391 whitelist_watcher.cpp:77] No whitelist given
> I1209 09:32:06.821907 31377 hierarchical.cpp:163] Initialized hierarchical
> allocator process
> I1209 09:32:06.823684 31378 master.cpp:1637] The newly elected leader is
> master@172.17.0.1:36768 with id 8915e203-6fb7-47de-9efa-cbd35e80f323
> I1209 09:32:06.823719 31378 master.cpp:1650] Elected as the leading master!
> I1209 09:32:06.823737 31378 master.cpp:1395] Recovering from registrar
> I1209 09:32:06.823873 31387 registrar.cpp:307] Recovering registrar
> I1209 09:32:06.853055 31389 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 33.032348ms
> I1209 09:32:06.853157 31389 replica.cpp:321] Persisted replica status to
> STARTING
> I1209 09:32:06.853531 31389 recover.cpp:473] Replica is in STARTING status
> I1209 09:32:06.855343 31379 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11516)@172.17.0.1:36768
> I1209 09:32:06.855840 31383 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1209 09:32:06.856336 31386 recover.cpp:564] Updating replica status to
> VOTING
> I1209 09:32:06.895592 31391 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 39.103912ms
> I1209 09:32:06.895684 31391 replica.cpp:321] Persisted replica status to
> VOTING
> I1209 09:32:06.895869 31378 recover.cpp:578] Successfully joined the Paxos
> group
> I1209 09:32:06.896136 31378 recover.cpp:462] Recover process terminated
> I1209 09:32:06.896723 31390 log.cpp:659] Attempting to start the writer
> I1209 09:32:06.898171 31378 replica.cpp:494] Replica received implicit
> promise request from (11517)@172.17.0.1:36768 with proposal 1
> I1209 09:32:06.924674 31378 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 26.4232ms
> I1209 09:32:06.924772 31378 replica.cpp:343] Persisted promised to 1
> I1209 09:32:06.925838 31380 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1209 09:32:06.927286 31380 replica.cpp:389] Replica received explicit
> promise request from (11518)@172.17.0.1:36768 for position 0 with
> proposal 2
> I1209 09:32:06.954188 31380 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 26.833246ms
> I1209 09:32:06.954282 31380 replica.cpp:713] Persisted action at 0
> I1209 09:32:06.955729 31387 replica.cpp:538] Replica received write
> request for position 0 from (11519)@172.17.0.1:36768
> I1209 09:32:06.955826 31387 leveldb.cpp:436] Reading position from leveldb
> took 50854ns
> I1209 09:32:06.979249 31387 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 23.341471ms
> I1209 09:32:06.979357 31387 replica.cpp:713] Persisted action at 0
> I1209 09:32:06.980240 31378 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1209 09:32:07.019819 31378 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 39.51368ms
> I1209 09:32:07.019927 31378 replica.cpp:713] Persisted action at 0
> I1209 09:32:07.019968 31378 replica.cpp:698] Replica learned NOP action at
> position 0
> I1209 09:32:07.021224 31381 log.cpp:675] Writer started with ending
> position 0
> I1209 09:32:07.022801 31389 leveldb.cpp:436] Reading position from leveldb
> took 59387ns
> I1209 09:32:07.024235 31389 registrar.cpp:340] Successfully fetched the
> registry (0B) in 200.247808ms
> I1209 09:32:07.024372 31389 registrar.cpp:439] Applied 1 operations in
> 41092ns; attempting to update the 'registry'
> I1209 09:32:07.025378 31388 log.cpp:683] Attempting to append 170 bytes to
> the log
> I1209 09:32:07.025638 31388 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1209 09:32:07.026530 31379 replica.cpp:538] Replica received write
> request for position 1 from (11520)@172.17.0.1:36768
> I1209 09:32:07.086838 31379 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 60.248143ms
> I1209 09:32:07.086911 31379 replica.cpp:713] Persisted action at 1
> I1209 09:32:07.087846 31381 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1209 09:32:07.154490 31381 leveldb.cpp:341] Persisting action (191
> bytes) to leveldb took 66.583158ms
> I1209 09:32:07.154594 31381 replica.cpp:713] Persisted action at 1
> I1209 09:32:07.154631 31381 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1209 09:32:07.156275 31381 registrar.cpp:484] Successfully updated the
> 'registry' in 131.830272ms
> I1209 09:32:07.156594 31383 log.cpp:702] Attempting to truncate the log to
> 1
> I1209 09:32:07.156735 31386 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1209 09:32:07.156837 31381 registrar.cpp:370] Successfully recovered
> registrar
> I1209 09:32:07.157815 31386 master.cpp:1447] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I1209 09:32:07.157964 31386 hierarchical.cpp:181] Skipping recovery of
> hierarchical allocator: nothing to recover
> I1209 09:32:07.158586 31383 replica.cpp:538] Replica received write
> request for position 2 from (11521)@172.17.0.1:36768
> I1209 09:32:07.205066 31383 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 46.418202ms
> I1209 09:32:07.205185 31383 replica.cpp:713] Persisted action at 2
> I1209 09:32:07.205989 31385 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1209 09:32:07.246814 31385 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 40.756064ms
> I1209 09:32:07.246989 31385 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 81265ns
> I1209 09:32:07.247019 31385 replica.cpp:713] Persisted action at 2
> I1209 09:32:07.247056 31385 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1209 09:32:07.249804 31357 scheduler.cpp:154] Version: 0.27.0
> I1209 09:32:07.250484 31379 scheduler.cpp:236] New master detected at
> master@172.17.0.1:36768
> I1209 09:32:07.251698 31378 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.1:36768
> I1209 09:32:07.253449 31381 process.cpp:3077] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1209 09:32:07.253512 31381 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.1:60233
> I1209 09:32:07.253681 31381 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1209 09:32:07.253746 31381 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1209 09:32:07.254040 31381 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I1209 09:32:07.254415 31388 hierarchical.cpp:267] Added framework
> 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
> I1209 09:32:07.254474 31387 master.hpp:1583] Sending heartbeat to
> 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
> I1209 09:32:07.254487 31388 hierarchical.cpp:1317] No resources available
> to allocate!
> I1209 09:32:07.254516 31388 hierarchical.cpp:1410] No inverse offers to
> send out!
> I1209 09:32:07.254536 31388 hierarchical.cpp:1063] Performed allocation
> for 0 slaves in 96195ns
> I1209 09:32:07.255125 31388 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.1:36768
> I1209 09:32:07.255625 31388 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.1:36768
> I1209 09:32:07.256796 31389 master_maintenance_tests.cpp:177] Ignoring
> HEARTBEAT event
> I1209 09:32:07.257036 31388 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.1:36768
> I1209 09:32:07.258867 31389 process.cpp:3077] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1209 09:32:07.258934 31389 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.1:60234
> I1209 09:32:07.259044 31389 master.cpp:2646] Processing REQUEST call for
> framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000 (default)
> I1209 09:32:07.259323 31383 hierarchical.cpp:562] Received resource
> request from framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
> I1209 09:32:07.259737 31389 master.cpp:938] Master terminating
> I1209 09:32:07.260293 31377 hierarchical.cpp:308] Removed framework
> 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
> E1209 09:32:07.261592 31376 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/0 (639 ms)
> [ RUN ] ContentType/SchedulerTest.Request/1
> I1209 09:32:07.410594 31357 leveldb.cpp:174] Opened db in 120.287264ms
> I1209 09:32:07.456307 31357 leveldb.cpp:181] Compacted db in 45.639439ms
> I1209 09:32:07.456403 31357 leveldb.cpp:196] Created db iterator in 25579ns
> I1209 09:32:07.456425 31357 leveldb.cpp:202] Seeked to beginning of db in
> 3065ns
> I1209 09:32:07.456439 31357 leveldb.cpp:271] Iterated through 0 keys in
> the db in 278ns
> I1209 09:32:07.456493 31357 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1209 09:32:07.457003 31378 recover.cpp:447] Starting replica recovery
> I1209 09:32:07.457243 31378 recover.cpp:473] Replica is in EMPTY status
> I1209 09:32:07.458528 31381 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11526)@172.17.0.1:36768
> I1209 09:32:07.458887 31390 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1209 09:32:07.459317 31390 recover.cpp:564] Updating replica status to
> STARTING
> I1209 09:32:07.459594 31388 master.cpp:365] Master
> 1680fc08-7c52-47c2-99b5-d62360e90018 (83469567f7e5) started on
> 172.17.0.1:36768
> I1209 09:32:07.459617 31388 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/TZoGb5/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/TZoGb5/master" --zk_session_timeout="10secs"
> I1209 09:32:07.459890 31388 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1209 09:32:07.459903 31388 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1209 09:32:07.459908 31388 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/TZoGb5/credentials'
> I1209 09:32:07.460166 31388 master.cpp:456] Using default 'crammd5'
> authenticator
> I1209 09:32:07.460276 31388 master.cpp:493] Authorization enabled
> I1209 09:32:07.460480 31383 whitelist_watcher.cpp:77] No whitelist given
> I1209 09:32:07.460532 31391 hierarchical.cpp:163] Initialized hierarchical
> allocator process
> I1209 09:32:07.461850 31389 master.cpp:1637] The newly elected leader is
> master@172.17.0.1:36768 with id 1680fc08-7c52-47c2-99b5-d62360e90018
> I1209 09:32:07.461876 31389 master.cpp:1650] Elected as the leading master!
> I1209 09:32:07.461891 31389 master.cpp:1395] Recovering from registrar
> I1209 09:32:07.462021 31379 registrar.cpp:307] Recovering registrar
> I1209 09:32:07.497812 31386 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 38.399797ms
> I1209 09:32:07.497858 31386 replica.cpp:321] Persisted replica status to
> STARTING
> I1209 09:32:07.498102 31384 recover.cpp:473] Replica is in STARTING status
> I1209 09:32:07.499070 31380 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11527)@172.17.0.1:36768
> I1209 09:32:07.499460 31386 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1209 09:32:07.499842 31387 recover.cpp:564] Updating replica status to
> VOTING
> I1209 09:32:07.547943 31378 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 47.93988ms
> I1209 09:32:07.548034 31378 replica.cpp:321] Persisted replica status to
> VOTING
> I1209 09:32:07.548285 31379 recover.cpp:578] Successfully joined the Paxos
> group
> I1209 09:32:07.548562 31379 recover.cpp:462] Recover process terminated
> I1209 09:32:07.549141 31378 log.cpp:659] Attempting to start the writer
> I1209 09:32:07.550566 31384 replica.cpp:494] Replica received implicit
> promise request from (11528)@172.17.0.1:36768 with proposal 1
> I1209 09:32:07.598314 31384 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 47.687289ms
> I1209 09:32:07.598367 31384 replica.cpp:343] Persisted promised to 1
> I1209 09:32:07.599102 31391 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1209 09:32:07.600304 31383 replica.cpp:389] Replica received explicit
> promise request from (11529)@172.17.0.1:36768 for position 0 with
> proposal 2
> I1209 09:32:07.656832 31383 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 56.474596ms
> I1209 09:32:07.656904 31383 replica.cpp:713] Persisted action at 0
> I1209 09:32:07.658511 31383 replica.cpp:538] Replica received write
> request for position 0 from (11530)@172.17.0.1:36768
> I1209 09:32:07.658586 31383 leveldb.cpp:436] Reading position from leveldb
> took 38613ns
> I1209 09:32:07.723805 31383 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 65.156434ms
> I1209 09:32:07.723893 31383 replica.cpp:713] Persisted action at 0
> I1209 09:32:07.724550 31379 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1209 09:32:07.781599 31379 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 56.997653ms
> I1209 09:32:07.781684 31379 replica.cpp:713] Persisted action at 0
> I1209 09:32:07.781721 31379 replica.cpp:698] Replica learned NOP action at
> position 0
> I1209 09:32:07.782536 31376 log.cpp:675] Writer started with ending
> position 0
> I1209 09:32:07.783665 31390 leveldb.cpp:436] Reading position from leveldb
> took 45513ns
> I1209 09:32:07.784554 31379 registrar.cpp:340] Successfully fetched the
> registry (0B) in 322.489088ms
> I1209 09:32:07.784684 31379 registrar.cpp:439] Applied 1 operations in
> 34759ns; attempting to update the 'registry'
> I1209 09:32:07.785341 31379 log.cpp:683] Attempting to append 170 bytes to
> the log
> I1209 09:32:07.785446 31381 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1209 09:32:07.786103 31391 replica.cpp:538] Replica received write
> request for position 1 from (11531)@172.17.0.1:36768
> I1209 09:32:07.819190 31391 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 33.031125ms
> I1209 09:32:07.819267 31391 replica.cpp:713] Persisted action at 1
> I1209 09:32:07.820041 31383 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1209 09:32:07.852705 31383 leveldb.cpp:341] Persisting action (191 bytes)
> to leveldb took 32.6269ms
> I1209 09:32:07.852741 31383 replica.cpp:713] Persisted action at 1
> I1209 09:32:07.852761 31383 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1209 09:32:07.854176 31377 registrar.cpp:484] Successfully updated the
> 'registry' in 69.390848ms
> I1209 09:32:07.854328 31377 registrar.cpp:370] Successfully recovered
> registrar
> I1209 09:32:07.854400 31387 log.cpp:702] Attempting to truncate the log to
> 1
> I1209 09:32:07.854526 31391 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1209 09:32:07.854773 31386 master.cpp:1447] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I1209 09:32:07.854796 31378 hierarchical.cpp:181] Skipping recovery of
> hierarchical allocator: nothing to recover
> I1209 09:32:07.855389 31385 replica.cpp:538] Replica received write
> request for position 2 from (11532)@172.17.0.1:36768
> I1209 09:32:07.907182 31385 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 51.739212ms
> I1209 09:32:07.907260 31385 replica.cpp:713] Persisted action at 2
> I1209 09:32:07.908494 31388 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1209 09:32:07.940865 31388 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 32.317321ms
> I1209 09:32:07.941011 31388 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 69012ns
> I1209 09:32:07.941032 31388 replica.cpp:713] Persisted action at 2
> I1209 09:32:07.941062 31388 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1209 09:32:07.946344 31357 scheduler.cpp:154] Version: 0.27.0
> I1209 09:32:07.947065 31384 scheduler.cpp:236] New master detected at
> master@172.17.0.1:36768
> I1209 09:32:07.948103 31389 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.1:36768
> I1209 09:32:07.950001 31383 process.cpp:3077] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1209 09:32:07.950091 31383 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.1:60235
> I1209 09:32:07.950531 31383 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1209 09:32:07.950629 31383 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1209 09:32:07.950975 31383 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I1209 09:32:07.951413 31378 hierarchical.cpp:267] Added framework
> 1680fc08-7c52-47c2-99b5-d62360e90018-0000
> I1209 09:32:07.951488 31378 hierarchical.cpp:1317] No resources available
> to allocate!
> I1209 09:32:07.951539 31378 hierarchical.cpp:1410] No inverse offers to
> send out!
> I1209 09:32:07.951581 31378 hierarchical.cpp:1063] Performed allocation
> for 0 slaves in 134318ns
> I1209 09:32:07.951586 31377 master.hpp:1583] Sending heartbeat to
> 1680fc08-7c52-47c2-99b5-d62360e90018-0000
> I1209 09:32:07.952893 31385 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.1:36768
> I1209 09:32:07.953416 31385 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.1:36768
> I1209 09:32:07.954185 31387 master_maintenance_tests.cpp:177] Ignoring
> HEARTBEAT event
> I1209 09:32:07.954236 31385 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.1:36768
> I1209 09:32:07.956225 31382 process.cpp:3077] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1209 09:32:07.956286 31382 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.1:60236
> I1209 09:32:07.956516 31382 master.cpp:2646] Processing REQUEST call for
> framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000 (default)
> I1209 09:32:07.956701 31378 hierarchical.cpp:562] Received resource
> request from framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000
> I1209 09:32:07.957008 31386 master.cpp:938] Master terminating
> I1209 09:32:07.957223 31381 hierarchical.cpp:308] Removed framework
> 1680fc08-7c52-47c2-99b5-d62360e90018-0000
> E1209 09:32:07.958663 31390 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/1 (687 ms)
> [----------] 22 tests from ContentType/SchedulerTest (18095 ms total)
>
> [----------] Global test environment tear-down
> [==========] 882 tests from 116 test cases ran. (753877 ms total)
> [ PASSED ] 881 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] HealthCheckTest.CheckCommandTimeout
>
> 1 FAILED TEST
> 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-1449651229-23195
> Untagged: mesos-1449651229-23195:latest
> Deleted: 051565f9dfe3b37571fcfc7225930eb1c9d806629c33952287641f755b17e648
> Deleted: 76f05c3d156a337001e19c53ee0089083a6dc922de46bbb202a486969497a4e1
> Deleted: 4e907babd3983c5c0c72fba97e69b6d0670dd2945061a49bad031bd68b290daf
> Deleted: d186ff9dacf7949bf93e6c6dbfbb53fc4f268e9782a6fd48ccfb142f8a5d0112
> Deleted: 3b7d54a77175b00bc4fa7fd4a5dea711b7383e41e5efc10d513e02e8ad4b8763
> Deleted: 061beb57666c931fb599b74a149846056d4db2294812ffc5a0cd12664fd0588b
> Deleted: 1d0e1e66610c9735084f523c2644fe7238c7b7cf137f14b8320c1943e1780261
> Deleted: d114981eca7dfc2c913d623463f72998a8a5e5e32eb7befb799029a2c2029886
> Deleted: dd3a65c7fab0c0db3b2fde67dc759d9825fdb4beec1976d9e543fcfa73fab348
> Deleted: 433ee4c743b4ab476a993ec91560fdbaa00bd769174569c7c213a5c56720e800
> Deleted: 4bbc0d8765d56ef2ee58507d3361a343536d61446f642b5e220f48050a69f502
> Deleted: 8419c976b238aa68af7b1bd55bc23c0c53cddd5f089331bb875ba185601de5f1
> Build step 'Execute shell' marked build as failure
>
Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1336
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1336/changes>
Changes:
[tnachen] Add mesos provisioner doc.
------------------------------------------
[...truncated 153346 lines...]
I1209 09:32:06.646441 31386 slave.cpp:3859] Cleaning up executor 'default' of framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000 at executor(135)@172.17.0.1:36768
I1209 09:32:06.646623 31383 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000/executors/default/runs/995547a3-580a-4852-a3de-9c947f10e9b6' for gc 6.99999251674667days in the future
I1209 09:32:06.646757 31386 slave.cpp:3947] Cleaning up framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
I1209 09:32:06.646775 31383 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000/executors/default' for gc 6.99999251503407days in the future
I1209 09:32:06.646872 31378 status_update_manager.cpp:282] Closing status update streams for framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
I1209 09:32:06.646934 31378 status_update_manager.cpp:528] Cleaning up status update stream for task 5bcaf46a-6505-47fc-bb3c-b47682ea632e of framework 5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000
I1209 09:32:06.646956 31389 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_hnwizd/slaves/5fb5da44-0c67-4ea6-b01c-da448034d0b6-S0/frameworks/5fb5da44-0c67-4ea6-b01c-da448034d0b6-0000' for gc 6.99999251305481days in the future
[ OK ] ContentType/SchedulerTest.Message/1 (626 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I1209 09:32:06.764993 31357 leveldb.cpp:174] Opened db in 113.871537ms
I1209 09:32:06.816138 31357 leveldb.cpp:181] Compacted db in 51.06532ms
I1209 09:32:06.816267 31357 leveldb.cpp:196] Created db iterator in 30876ns
I1209 09:32:06.816283 31357 leveldb.cpp:202] Seeked to beginning of db in 4150ns
I1209 09:32:06.816292 31357 leveldb.cpp:271] Iterated through 0 keys in the db in 251ns
I1209 09:32:06.816346 31357 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1209 09:32:06.817158 31391 recover.cpp:447] Starting replica recovery
I1209 09:32:06.817488 31391 recover.cpp:473] Replica is in EMPTY status
I1209 09:32:06.818835 31376 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11515)@172.17.0.1:36768
I1209 09:32:06.819315 31387 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1209 09:32:06.819808 31382 recover.cpp:564] Updating replica status to STARTING
I1209 09:32:06.820646 31381 master.cpp:365] Master 8915e203-6fb7-47de-9efa-cbd35e80f323 (83469567f7e5) started on 172.17.0.1:36768
I1209 09:32:06.820677 31381 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/EXBunl/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/EXBunl/master" --zk_session_timeout="10secs"
I1209 09:32:06.821024 31381 master.cpp:414] Master allowing unauthenticated frameworks to register
I1209 09:32:06.821053 31381 master.cpp:417] Master only allowing authenticated slaves to register
I1209 09:32:06.821072 31381 credentials.hpp:35] Loading credentials for authentication from '/tmp/EXBunl/credentials'
I1209 09:32:06.821445 31381 master.cpp:456] Using default 'crammd5' authenticator
I1209 09:32:06.821604 31381 master.cpp:493] Authorization enabled
I1209 09:32:06.821856 31391 whitelist_watcher.cpp:77] No whitelist given
I1209 09:32:06.821907 31377 hierarchical.cpp:163] Initialized hierarchical allocator process
I1209 09:32:06.823684 31378 master.cpp:1637] The newly elected leader is master@172.17.0.1:36768 with id 8915e203-6fb7-47de-9efa-cbd35e80f323
I1209 09:32:06.823719 31378 master.cpp:1650] Elected as the leading master!
I1209 09:32:06.823737 31378 master.cpp:1395] Recovering from registrar
I1209 09:32:06.823873 31387 registrar.cpp:307] Recovering registrar
I1209 09:32:06.853055 31389 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 33.032348ms
I1209 09:32:06.853157 31389 replica.cpp:321] Persisted replica status to STARTING
I1209 09:32:06.853531 31389 recover.cpp:473] Replica is in STARTING status
I1209 09:32:06.855343 31379 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11516)@172.17.0.1:36768
I1209 09:32:06.855840 31383 recover.cpp:193] Received a recover response from a replica in STARTING status
I1209 09:32:06.856336 31386 recover.cpp:564] Updating replica status to VOTING
I1209 09:32:06.895592 31391 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 39.103912ms
I1209 09:32:06.895684 31391 replica.cpp:321] Persisted replica status to VOTING
I1209 09:32:06.895869 31378 recover.cpp:578] Successfully joined the Paxos group
I1209 09:32:06.896136 31378 recover.cpp:462] Recover process terminated
I1209 09:32:06.896723 31390 log.cpp:659] Attempting to start the writer
I1209 09:32:06.898171 31378 replica.cpp:494] Replica received implicit promise request from (11517)@172.17.0.1:36768 with proposal 1
I1209 09:32:06.924674 31378 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 26.4232ms
I1209 09:32:06.924772 31378 replica.cpp:343] Persisted promised to 1
I1209 09:32:06.925838 31380 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1209 09:32:06.927286 31380 replica.cpp:389] Replica received explicit promise request from (11518)@172.17.0.1:36768 for position 0 with proposal 2
I1209 09:32:06.954188 31380 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 26.833246ms
I1209 09:32:06.954282 31380 replica.cpp:713] Persisted action at 0
I1209 09:32:06.955729 31387 replica.cpp:538] Replica received write request for position 0 from (11519)@172.17.0.1:36768
I1209 09:32:06.955826 31387 leveldb.cpp:436] Reading position from leveldb took 50854ns
I1209 09:32:06.979249 31387 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 23.341471ms
I1209 09:32:06.979357 31387 replica.cpp:713] Persisted action at 0
I1209 09:32:06.980240 31378 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1209 09:32:07.019819 31378 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 39.51368ms
I1209 09:32:07.019927 31378 replica.cpp:713] Persisted action at 0
I1209 09:32:07.019968 31378 replica.cpp:698] Replica learned NOP action at position 0
I1209 09:32:07.021224 31381 log.cpp:675] Writer started with ending position 0
I1209 09:32:07.022801 31389 leveldb.cpp:436] Reading position from leveldb took 59387ns
I1209 09:32:07.024235 31389 registrar.cpp:340] Successfully fetched the registry (0B) in 200.247808ms
I1209 09:32:07.024372 31389 registrar.cpp:439] Applied 1 operations in 41092ns; attempting to update the 'registry'
I1209 09:32:07.025378 31388 log.cpp:683] Attempting to append 170 bytes to the log
I1209 09:32:07.025638 31388 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1209 09:32:07.026530 31379 replica.cpp:538] Replica received write request for position 1 from (11520)@172.17.0.1:36768
I1209 09:32:07.086838 31379 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 60.248143ms
I1209 09:32:07.086911 31379 replica.cpp:713] Persisted action at 1
I1209 09:32:07.087846 31381 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1209 09:32:07.154490 31381 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 66.583158ms
I1209 09:32:07.154594 31381 replica.cpp:713] Persisted action at 1
I1209 09:32:07.154631 31381 replica.cpp:698] Replica learned APPEND action at position 1
I1209 09:32:07.156275 31381 registrar.cpp:484] Successfully updated the 'registry' in 131.830272ms
I1209 09:32:07.156594 31383 log.cpp:702] Attempting to truncate the log to 1
I1209 09:32:07.156735 31386 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1209 09:32:07.156837 31381 registrar.cpp:370] Successfully recovered registrar
I1209 09:32:07.157815 31386 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1209 09:32:07.157964 31386 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1209 09:32:07.158586 31383 replica.cpp:538] Replica received write request for position 2 from (11521)@172.17.0.1:36768
I1209 09:32:07.205066 31383 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 46.418202ms
I1209 09:32:07.205185 31383 replica.cpp:713] Persisted action at 2
I1209 09:32:07.205989 31385 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1209 09:32:07.246814 31385 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 40.756064ms
I1209 09:32:07.246989 31385 leveldb.cpp:399] Deleting ~1 keys from leveldb took 81265ns
I1209 09:32:07.247019 31385 replica.cpp:713] Persisted action at 2
I1209 09:32:07.247056 31385 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1209 09:32:07.249804 31357 scheduler.cpp:154] Version: 0.27.0
I1209 09:32:07.250484 31379 scheduler.cpp:236] New master detected at master@172.17.0.1:36768
I1209 09:32:07.251698 31378 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.1:36768
I1209 09:32:07.253449 31381 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 09:32:07.253512 31381 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:60233
I1209 09:32:07.253681 31381 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1209 09:32:07.253746 31381 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1209 09:32:07.254040 31381 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1209 09:32:07.254415 31388 hierarchical.cpp:267] Added framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
I1209 09:32:07.254474 31387 master.hpp:1583] Sending heartbeat to 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
I1209 09:32:07.254487 31388 hierarchical.cpp:1317] No resources available to allocate!
I1209 09:32:07.254516 31388 hierarchical.cpp:1410] No inverse offers to send out!
I1209 09:32:07.254536 31388 hierarchical.cpp:1063] Performed allocation for 0 slaves in 96195ns
I1209 09:32:07.255125 31388 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.1:36768
I1209 09:32:07.255625 31388 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.1:36768
I1209 09:32:07.256796 31389 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I1209 09:32:07.257036 31388 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.1:36768
I1209 09:32:07.258867 31389 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 09:32:07.258934 31389 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:60234
I1209 09:32:07.259044 31389 master.cpp:2646] Processing REQUEST call for framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000 (default)
I1209 09:32:07.259323 31383 hierarchical.cpp:562] Received resource request from framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
I1209 09:32:07.259737 31389 master.cpp:938] Master terminating
I1209 09:32:07.260293 31377 hierarchical.cpp:308] Removed framework 8915e203-6fb7-47de-9efa-cbd35e80f323-0000
E1209 09:32:07.261592 31376 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (639 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I1209 09:32:07.410594 31357 leveldb.cpp:174] Opened db in 120.287264ms
I1209 09:32:07.456307 31357 leveldb.cpp:181] Compacted db in 45.639439ms
I1209 09:32:07.456403 31357 leveldb.cpp:196] Created db iterator in 25579ns
I1209 09:32:07.456425 31357 leveldb.cpp:202] Seeked to beginning of db in 3065ns
I1209 09:32:07.456439 31357 leveldb.cpp:271] Iterated through 0 keys in the db in 278ns
I1209 09:32:07.456493 31357 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1209 09:32:07.457003 31378 recover.cpp:447] Starting replica recovery
I1209 09:32:07.457243 31378 recover.cpp:473] Replica is in EMPTY status
I1209 09:32:07.458528 31381 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11526)@172.17.0.1:36768
I1209 09:32:07.458887 31390 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1209 09:32:07.459317 31390 recover.cpp:564] Updating replica status to STARTING
I1209 09:32:07.459594 31388 master.cpp:365] Master 1680fc08-7c52-47c2-99b5-d62360e90018 (83469567f7e5) started on 172.17.0.1:36768
I1209 09:32:07.459617 31388 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/TZoGb5/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/TZoGb5/master" --zk_session_timeout="10secs"
I1209 09:32:07.459890 31388 master.cpp:414] Master allowing unauthenticated frameworks to register
I1209 09:32:07.459903 31388 master.cpp:417] Master only allowing authenticated slaves to register
I1209 09:32:07.459908 31388 credentials.hpp:35] Loading credentials for authentication from '/tmp/TZoGb5/credentials'
I1209 09:32:07.460166 31388 master.cpp:456] Using default 'crammd5' authenticator
I1209 09:32:07.460276 31388 master.cpp:493] Authorization enabled
I1209 09:32:07.460480 31383 whitelist_watcher.cpp:77] No whitelist given
I1209 09:32:07.460532 31391 hierarchical.cpp:163] Initialized hierarchical allocator process
I1209 09:32:07.461850 31389 master.cpp:1637] The newly elected leader is master@172.17.0.1:36768 with id 1680fc08-7c52-47c2-99b5-d62360e90018
I1209 09:32:07.461876 31389 master.cpp:1650] Elected as the leading master!
I1209 09:32:07.461891 31389 master.cpp:1395] Recovering from registrar
I1209 09:32:07.462021 31379 registrar.cpp:307] Recovering registrar
I1209 09:32:07.497812 31386 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 38.399797ms
I1209 09:32:07.497858 31386 replica.cpp:321] Persisted replica status to STARTING
I1209 09:32:07.498102 31384 recover.cpp:473] Replica is in STARTING status
I1209 09:32:07.499070 31380 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11527)@172.17.0.1:36768
I1209 09:32:07.499460 31386 recover.cpp:193] Received a recover response from a replica in STARTING status
I1209 09:32:07.499842 31387 recover.cpp:564] Updating replica status to VOTING
I1209 09:32:07.547943 31378 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 47.93988ms
I1209 09:32:07.548034 31378 replica.cpp:321] Persisted replica status to VOTING
I1209 09:32:07.548285 31379 recover.cpp:578] Successfully joined the Paxos group
I1209 09:32:07.548562 31379 recover.cpp:462] Recover process terminated
I1209 09:32:07.549141 31378 log.cpp:659] Attempting to start the writer
I1209 09:32:07.550566 31384 replica.cpp:494] Replica received implicit promise request from (11528)@172.17.0.1:36768 with proposal 1
I1209 09:32:07.598314 31384 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 47.687289ms
I1209 09:32:07.598367 31384 replica.cpp:343] Persisted promised to 1
I1209 09:32:07.599102 31391 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1209 09:32:07.600304 31383 replica.cpp:389] Replica received explicit promise request from (11529)@172.17.0.1:36768 for position 0 with proposal 2
I1209 09:32:07.656832 31383 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 56.474596ms
I1209 09:32:07.656904 31383 replica.cpp:713] Persisted action at 0
I1209 09:32:07.658511 31383 replica.cpp:538] Replica received write request for position 0 from (11530)@172.17.0.1:36768
I1209 09:32:07.658586 31383 leveldb.cpp:436] Reading position from leveldb took 38613ns
I1209 09:32:07.723805 31383 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 65.156434ms
I1209 09:32:07.723893 31383 replica.cpp:713] Persisted action at 0
I1209 09:32:07.724550 31379 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1209 09:32:07.781599 31379 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 56.997653ms
I1209 09:32:07.781684 31379 replica.cpp:713] Persisted action at 0
I1209 09:32:07.781721 31379 replica.cpp:698] Replica learned NOP action at position 0
I1209 09:32:07.782536 31376 log.cpp:675] Writer started with ending position 0
I1209 09:32:07.783665 31390 leveldb.cpp:436] Reading position from leveldb took 45513ns
I1209 09:32:07.784554 31379 registrar.cpp:340] Successfully fetched the registry (0B) in 322.489088ms
I1209 09:32:07.784684 31379 registrar.cpp:439] Applied 1 operations in 34759ns; attempting to update the 'registry'
I1209 09:32:07.785341 31379 log.cpp:683] Attempting to append 170 bytes to the log
I1209 09:32:07.785446 31381 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1209 09:32:07.786103 31391 replica.cpp:538] Replica received write request for position 1 from (11531)@172.17.0.1:36768
I1209 09:32:07.819190 31391 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 33.031125ms
I1209 09:32:07.819267 31391 replica.cpp:713] Persisted action at 1
I1209 09:32:07.820041 31383 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1209 09:32:07.852705 31383 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 32.6269ms
I1209 09:32:07.852741 31383 replica.cpp:713] Persisted action at 1
I1209 09:32:07.852761 31383 replica.cpp:698] Replica learned APPEND action at position 1
I1209 09:32:07.854176 31377 registrar.cpp:484] Successfully updated the 'registry' in 69.390848ms
I1209 09:32:07.854328 31377 registrar.cpp:370] Successfully recovered registrar
I1209 09:32:07.854400 31387 log.cpp:702] Attempting to truncate the log to 1
I1209 09:32:07.854526 31391 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1209 09:32:07.854773 31386 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1209 09:32:07.854796 31378 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1209 09:32:07.855389 31385 replica.cpp:538] Replica received write request for position 2 from (11532)@172.17.0.1:36768
I1209 09:32:07.907182 31385 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 51.739212ms
I1209 09:32:07.907260 31385 replica.cpp:713] Persisted action at 2
I1209 09:32:07.908494 31388 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1209 09:32:07.940865 31388 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 32.317321ms
I1209 09:32:07.941011 31388 leveldb.cpp:399] Deleting ~1 keys from leveldb took 69012ns
I1209 09:32:07.941032 31388 replica.cpp:713] Persisted action at 2
I1209 09:32:07.941062 31388 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1209 09:32:07.946344 31357 scheduler.cpp:154] Version: 0.27.0
I1209 09:32:07.947065 31384 scheduler.cpp:236] New master detected at master@172.17.0.1:36768
I1209 09:32:07.948103 31389 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.1:36768
I1209 09:32:07.950001 31383 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 09:32:07.950091 31383 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:60235
I1209 09:32:07.950531 31383 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1209 09:32:07.950629 31383 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1209 09:32:07.950975 31383 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I1209 09:32:07.951413 31378 hierarchical.cpp:267] Added framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000
I1209 09:32:07.951488 31378 hierarchical.cpp:1317] No resources available to allocate!
I1209 09:32:07.951539 31378 hierarchical.cpp:1410] No inverse offers to send out!
I1209 09:32:07.951581 31378 hierarchical.cpp:1063] Performed allocation for 0 slaves in 134318ns
I1209 09:32:07.951586 31377 master.hpp:1583] Sending heartbeat to 1680fc08-7c52-47c2-99b5-d62360e90018-0000
I1209 09:32:07.952893 31385 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.1:36768
I1209 09:32:07.953416 31385 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.1:36768
I1209 09:32:07.954185 31387 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I1209 09:32:07.954236 31385 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.1:36768
I1209 09:32:07.956225 31382 process.cpp:3077] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1209 09:32:07.956286 31382 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.1:60236
I1209 09:32:07.956516 31382 master.cpp:2646] Processing REQUEST call for framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000 (default)
I1209 09:32:07.956701 31378 hierarchical.cpp:562] Received resource request from framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000
I1209 09:32:07.957008 31386 master.cpp:938] Master terminating
I1209 09:32:07.957223 31381 hierarchical.cpp:308] Removed framework 1680fc08-7c52-47c2-99b5-d62360e90018-0000
E1209 09:32:07.958663 31390 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (687 ms)
[----------] 22 tests from ContentType/SchedulerTest (18095 ms total)
[----------] Global test environment tear-down
[==========] 882 tests from 116 test cases ran. (753877 ms total)
[ PASSED ] 881 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] HealthCheckTest.CheckCommandTimeout
1 FAILED TEST
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-1449651229-23195
Untagged: mesos-1449651229-23195:latest
Deleted: 051565f9dfe3b37571fcfc7225930eb1c9d806629c33952287641f755b17e648
Deleted: 76f05c3d156a337001e19c53ee0089083a6dc922de46bbb202a486969497a4e1
Deleted: 4e907babd3983c5c0c72fba97e69b6d0670dd2945061a49bad031bd68b290daf
Deleted: d186ff9dacf7949bf93e6c6dbfbb53fc4f268e9782a6fd48ccfb142f8a5d0112
Deleted: 3b7d54a77175b00bc4fa7fd4a5dea711b7383e41e5efc10d513e02e8ad4b8763
Deleted: 061beb57666c931fb599b74a149846056d4db2294812ffc5a0cd12664fd0588b
Deleted: 1d0e1e66610c9735084f523c2644fe7238c7b7cf137f14b8320c1943e1780261
Deleted: d114981eca7dfc2c913d623463f72998a8a5e5e32eb7befb799029a2c2029886
Deleted: dd3a65c7fab0c0db3b2fde67dc759d9825fdb4beec1976d9e543fcfa73fab348
Deleted: 433ee4c743b4ab476a993ec91560fdbaa00bd769174569c7c213a5c56720e800
Deleted: 4bbc0d8765d56ef2ee58507d3361a343536d61446f642b5e220f48050a69f502
Deleted: 8419c976b238aa68af7b1bd55bc23c0c53cddd5f089331bb875ba185601de5f1
Build step 'Execute shell' marked build as failure