See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/2120/changes>
Changes: [vinod] Revert "Allowed Gauge to take synchronous functions." [vinod] Added test for killing unknown task with Slaves in transitional state. [niklas] Updated CHANGELOG for 0.18.2-rc1. [benjamin.hindman] Introduced '--' to flags parsing. [benjamin.hindman] Added override of Flags::load that updates 'argc' and 'argv'. [bmahler] Added task gauges to slave metrics. [niklas] Added support for passing flags in override command. [vinod] mesos-style.py accepts files to lint as args. [niklas] Temporarily disabled RunTaskWithCommandInfoWithUser due to MESOS-1359. [niklas] Fixed concurrent wait within the ExternalContainerizer. [bmahler] Ported some of the master stats to the new metrics library. [yan] Added message counters for all message types in Master. [bmahler] Updated Slave.MetricsInStatsEndpoint test to match latest metrics. [yujie.jay] Fixed a compiler warning from stout flags. [bmahler] Added task gauges to Master. [bmahler] Changed 'registry' flag default to 'replicated_log'. [yan] Fixed comment typos in a previous commit for message counters. [bmahler] Added resource Gauges to Master. [vinod] Fixed credentials::read() to properly stat the credentials file. [yujie.jay] Added API for managing links. [yujie.jay] Allowed to get/set MTU for a link. [yujie.jay] Added runtime check to the Linux routing library. [yujie.jay] Added internal filter and queueing APIs. [yujie.jay] Added API for managing ICMP packet filters. [yujie.jay] Added API for managing ARP packet filters. [yujie.jay] Added API for managing IP packet filters. [yujie.jay] Added API for getting the default gateway. [yujie.jay] Allowed waiting for a link to be removed. ------------------------------------------ [...truncated 21000 lines...] I0515 19:11:40.528422 1642 leveldb.cpp:198] Created db iterator in 4439ns I0515 19:11:40.528435 1642 leveldb.cpp:204] Seeked to beginning of db in 896ns I0515 19:11:40.528441 1642 leveldb.cpp:273] Iterated through 0 keys in the db in 325ns I0515 19:11:40.528455 1642 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0515 19:11:40.528712 1667 recover.cpp:425] Starting replica recovery I0515 19:11:40.528849 1667 recover.cpp:451] Replica is in EMPTY status I0515 19:11:40.529289 1667 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I0515 19:11:40.529450 1665 recover.cpp:188] Received a recover response from a replica in EMPTY status I0515 19:11:40.529639 1661 recover.cpp:542] Updating replica status to STARTING I0515 19:11:40.529810 1662 master.cpp:269] Master 20140515-191140-160088899-45547-1642 (vesta.apache.org) started on 67.195.138.9:45547 I0515 19:11:40.529831 1662 master.cpp:306] Master only allowing authenticated frameworks to register I0515 19:11:40.529842 1662 master.cpp:311] Master only allowing authenticated slaves to register I0515 19:11:40.529849 1662 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_icVq5E/credentials' I0515 19:11:40.530112 1664 master.cpp:106] No whitelist given. Advertising offers for all slaves I0515 19:11:40.530182 1668 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@67.195.138.9:45547 I0515 19:11:40.530514 1667 master.cpp:923] The newly elected leader is master@67.195.138.9:45547 with id 20140515-191140-160088899-45547-1642 I0515 19:11:40.530525 1667 master.cpp:933] Elected as the leading master! I0515 19:11:40.530532 1667 master.cpp:754] Recovering from registrar I0515 19:11:40.530602 1664 registrar.cpp:313] Recovering registrar I0515 19:11:40.568043 1665 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 38.350201ms I0515 19:11:40.568068 1665 replica.cpp:320] Persisted replica status to STARTING I0515 19:11:40.568147 1665 recover.cpp:451] Replica is in STARTING status I0515 19:11:40.568500 1664 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I0515 19:11:40.568614 1663 recover.cpp:188] Received a recover response from a replica in STARTING status I0515 19:11:40.568790 1661 recover.cpp:542] Updating replica status to VOTING I0515 19:11:40.571449 1663 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 2.576402ms I0515 19:11:40.571470 1663 replica.cpp:320] Persisted replica status to VOTING I0515 19:11:40.571555 1666 recover.cpp:556] Successfully joined the Paxos group I0515 19:11:40.571673 1666 recover.cpp:440] Recover process terminated I0515 19:11:40.571816 1666 log.cpp:656] Attempting to start the writer I0515 19:11:40.572340 1668 replica.cpp:474] Replica received implicit promise request with proposal 1 I0515 19:11:40.579468 1668 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 7.111361ms I0515 19:11:40.579485 1668 replica.cpp:342] Persisted promised to 1 I0515 19:11:40.579781 1667 coordinator.cpp:230] Coordinator attemping to fill missing position I0515 19:11:40.580343 1665 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0515 19:11:40.599325 1665 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 18.931841ms I0515 19:11:40.599344 1665 replica.cpp:676] Persisted action at 0 I0515 19:11:40.599776 1662 replica.cpp:508] Replica received write request for position 0 I0515 19:11:40.599802 1662 leveldb.cpp:438] Reading position from leveldb took 12540ns I0515 19:11:40.607293 1662 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 7.477437ms I0515 19:11:40.607312 1662 replica.cpp:676] Persisted action at 0 I0515 19:11:40.607472 1662 replica.cpp:655] Replica received learned notice for position 0 I0515 19:11:40.615274 1662 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.72362ms I0515 19:11:40.615291 1662 replica.cpp:676] Persisted action at 0 I0515 19:11:40.615301 1662 replica.cpp:661] Replica learned NOP action at position 0 I0515 19:11:40.615531 1663 log.cpp:672] Writer started with ending position 0 I0515 19:11:40.615932 1664 leveldb.cpp:438] Reading position from leveldb took 15277ns I0515 19:11:40.617210 1667 registrar.cpp:346] Successfully fetched the registry (0B) I0515 19:11:40.617238 1667 registrar.cpp:422] Attempting to update the 'registry' I0515 19:11:40.618459 1663 log.cpp:680] Attempting to append 133 bytes to the log I0515 19:11:40.618517 1663 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0515 19:11:40.618831 1666 replica.cpp:508] Replica received write request for position 1 I0515 19:11:40.635179 1666 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 16.332541ms I0515 19:11:40.635198 1666 replica.cpp:676] Persisted action at 1 I0515 19:11:40.635409 1666 replica.cpp:655] Replica received learned notice for position 1 I0515 19:11:40.643151 1666 leveldb.cpp:343] Persisting action (154 bytes) to leveldb took 7.673383ms I0515 19:11:40.643167 1666 replica.cpp:676] Persisted action at 1 I0515 19:11:40.643177 1666 replica.cpp:661] Replica learned APPEND action at position 1 I0515 19:11:40.643466 1662 registrar.cpp:479] Successfully updated 'registry' I0515 19:11:40.643571 1663 log.cpp:699] Attempting to truncate the log to 1 I0515 19:11:40.643591 1662 registrar.cpp:372] Successfully recovered registrar I0515 19:11:40.643653 1667 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0515 19:11:40.643707 1661 master.cpp:781] Recovered 0 slaves from the Registry (96B) ; allowing 10mins for slaves to re-register I0515 19:11:40.643944 1664 replica.cpp:508] Replica received write request for position 2 I0515 19:11:40.644243 1642 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem I0515 19:11:40.646425 1662 slave.cpp:143] Slave started on 64)@67.195.138.9:45547 I0515 19:11:40.646440 1662 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/credential' I0515 19:11:40.646498 1662 slave.cpp:236] Slave using credential for: test-principal I0515 19:11:40.646615 1662 slave.cpp:249] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0515 19:11:40.646666 1662 slave.cpp:277] Slave hostname: vesta.apache.org I0515 19:11:40.646677 1662 slave.cpp:278] Slave checkpoint: true I0515 19:11:40.647181 1665 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta' I0515 19:11:40.647325 1665 status_update_manager.cpp:193] Recovering status update manager I0515 19:11:40.647434 1665 mesos_containerizer.cpp:279] Recovering containerizer I0515 19:11:40.647702 1665 slave.cpp:2965] Finished recovery I0515 19:11:40.647940 1665 slave.cpp:530] New master detected at master@67.195.138.9:45547 I0515 19:11:40.648005 1665 slave.cpp:590] Authenticating with master master@67.195.138.9:45547 I0515 19:11:40.648095 1665 slave.cpp:563] Detecting new master I0515 19:11:40.648175 1665 status_update_manager.cpp:167] New master detected at master@67.195.138.9:45547 I0515 19:11:40.648206 1642 sched.cpp:121] Version: 0.19.0 I0515 19:11:40.648262 1665 authenticatee.hpp:128] Creating new client SASL connection I0515 19:11:40.648483 1667 master.cpp:2841] Authenticating slave(64)@67.195.138.9:45547 I0515 19:11:40.648555 1663 authenticator.hpp:148] Creating new server SASL connection I0515 19:11:40.648569 1662 sched.cpp:217] New master detected at master@67.195.138.9:45547 I0515 19:11:40.648586 1662 sched.cpp:268] Authenticating with master master@67.195.138.9:45547 I0515 19:11:40.648627 1667 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0515 19:11:40.648635 1665 authenticatee.hpp:128] Creating new client SASL connection I0515 19:11:40.648648 1667 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0515 19:11:40.648731 1668 master.cpp:2841] Authenticating scheduler(57)@67.195.138.9:45547 I0515 19:11:40.648763 1665 authenticator.hpp:254] Received SASL authentication start I0515 19:11:40.648797 1667 authenticator.hpp:148] Creating new server SASL connection I0515 19:11:40.648800 1665 authenticator.hpp:342] Authentication requires more steps I0515 19:11:40.648847 1665 authenticatee.hpp:265] Received SASL authentication step I0515 19:11:40.648866 1667 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0515 19:11:40.648885 1667 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0515 19:11:40.648891 1665 authenticator.hpp:282] Received SASL authentication step I0515 19:11:40.648908 1665 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0515 19:11:40.648921 1665 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0515 19:11:40.648910 1667 authenticator.hpp:254] Received SASL authentication start I0515 19:11:40.648937 1665 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0515 19:11:40.648949 1665 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0515 19:11:40.648957 1665 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0515 19:11:40.648962 1665 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0515 19:11:40.648972 1667 authenticator.hpp:342] Authentication requires more steps I0515 19:11:40.648974 1665 authenticator.hpp:334] Authentication success I0515 19:11:40.649011 1667 authenticatee.hpp:265] Received SASL authentication step I0515 19:11:40.649027 1662 authenticatee.hpp:305] Authentication success I0515 19:11:40.649044 1665 master.cpp:2881] Successfully authenticated slave(64)@67.195.138.9:45547 I0515 19:11:40.649066 1667 authenticator.hpp:282] Received SASL authentication step I0515 19:11:40.649087 1667 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0515 19:11:40.649096 1667 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0515 19:11:40.649106 1667 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0515 19:11:40.649112 1662 slave.cpp:647] Successfully authenticated with master master@67.195.138.9:45547 I0515 19:11:40.649116 1667 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0515 19:11:40.649134 1667 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0515 19:11:40.649139 1667 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0515 19:11:40.649147 1662 slave.cpp:876] Will retry registration in 9.546662983secs if necessary I0515 19:11:40.649152 1667 authenticator.hpp:334] Authentication success I0515 19:11:40.649201 1667 authenticatee.hpp:305] Authentication success I0515 19:11:40.649340 1667 sched.cpp:342] Successfully authenticated with master master@67.195.138.9:45547 I0515 19:11:40.649348 1665 master.cpp:2157] Registering slave at slave(64)@67.195.138.9:45547 (vesta.apache.org) with id 20140515-191140-160088899-45547-1642-0 I0515 19:11:40.649353 1667 sched.cpp:461] Sending registration request to master@67.195.138.9:45547 I0515 19:11:40.649466 1665 master.cpp:2881] Successfully authenticated scheduler(57)@67.195.138.9:45547 I0515 19:11:40.649493 1663 registrar.cpp:422] Attempting to update the 'registry' I0515 19:11:40.649544 1665 master.cpp:982] Received registration request from scheduler(57)@67.195.138.9:45547 I0515 19:11:40.649588 1665 master.cpp:1000] Registering framework 20140515-191140-160088899-45547-1642-0000 at scheduler(57)@67.195.138.9:45547 I0515 19:11:40.649660 1662 sched.cpp:392] Framework registered with 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.649719 1662 sched.cpp:406] Scheduler::registered took 10138ns I0515 19:11:40.649690 1668 hierarchical_allocator_process.hpp:331] Added framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.649761 1668 hierarchical_allocator_process.hpp:725] No resources available to allocate! I0515 19:11:40.649770 1668 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 8803ns I0515 19:11:40.651123 1664 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.163446ms I0515 19:11:40.651139 1664 replica.cpp:676] Persisted action at 2 I0515 19:11:40.651329 1664 replica.cpp:655] Replica received learned notice for position 2 I0515 19:11:40.659086 1664 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.744393ms I0515 19:11:40.659114 1664 leveldb.cpp:401] Deleting ~1 keys from leveldb took 11927ns I0515 19:11:40.659124 1664 replica.cpp:676] Persisted action at 2 I0515 19:11:40.659132 1664 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0515 19:11:40.659458 1662 log.cpp:680] Attempting to append 325 bytes to the log I0515 19:11:40.659518 1666 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0515 19:11:40.659904 1663 replica.cpp:508] Replica received write request for position 3 I0515 19:11:40.667059 1663 leveldb.cpp:343] Persisting action (344 bytes) to leveldb took 7.14175ms I0515 19:11:40.667078 1663 replica.cpp:676] Persisted action at 3 I0515 19:11:40.667300 1664 replica.cpp:655] Replica received learned notice for position 3 I0515 19:11:40.675027 1664 leveldb.cpp:343] Persisting action (346 bytes) to leveldb took 7.711991ms I0515 19:11:40.675045 1664 replica.cpp:676] Persisted action at 3 I0515 19:11:40.675055 1664 replica.cpp:661] Replica learned APPEND action at position 3 I0515 19:11:40.675444 1667 registrar.cpp:479] Successfully updated 'registry' I0515 19:11:40.675531 1662 log.cpp:699] Attempting to truncate the log to 3 I0515 19:11:40.675576 1662 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0515 19:11:40.675618 1665 master.cpp:2197] Registered slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) I0515 19:11:40.675701 1665 master.cpp:3326] Adding slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0515 19:11:40.675823 1664 slave.cpp:680] Registered with master master@67.195.138.9:45547; given slave ID 20140515-191140-160088899-45547-1642-0 I0515 19:11:40.675935 1667 hierarchical_allocator_process.hpp:444] Added slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0515 19:11:40.676077 1667 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 to framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.676120 1664 slave.cpp:693] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/slave.info' I0515 19:11:40.676266 1667 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140515-191140-160088899-45547-1642-0 in 215235ns I0515 19:11:40.675957 1662 replica.cpp:508] Replica received write request for position 4 I0515 19:11:40.676331 1663 master.hpp:663] Adding offer 20140515-191140-160088899-45547-1642-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) I0515 19:11:40.676409 1663 master.cpp:2788] Sending 1 offers to framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.676535 1663 sched.cpp:529] Scheduler::resourceOffers took 25156ns I0515 19:11:40.677845 1661 master.hpp:673] Removing offer 20140515-191140-160088899-45547-1642-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) I0515 19:11:40.677906 1661 master.cpp:1822] Processing reply for offers: [ 20140515-191140-160088899-45547-1642-0 ] on slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) for framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.678022 1661 master.hpp:635] Adding task 3659da35-6351-4e38-84c5-f76bb3eca499 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) I0515 19:11:40.678073 1661 master.cpp:2965] Launching task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) I0515 19:11:40.678212 1661 slave.cpp:910] Got assigned task 3659da35-6351-4e38-84c5-f76bb3eca499 for framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.678288 1661 slave.cpp:3237] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/framework.info' I0515 19:11:40.678392 1661 slave.cpp:3244] Checkpointing framework pid 'scheduler(57)@67.195.138.9:45547' to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/framework.pid' I0515 19:11:40.678594 1661 slave.cpp:1020] Launching task 3659da35-6351-4e38-84c5-f76bb3eca499 for framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.679785 1661 slave.cpp:3559] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/executors/3659da35-6351-4e38-84c5-f76bb3eca499/executor.info' I0515 19:11:40.680172 1667 mesos_containerizer.cpp:523] Starting container '09947a0f-892b-4a60-8dc3-63424a50f207' for executor '3659da35-6351-4e38-84c5-f76bb3eca499' of framework '20140515-191140-160088899-45547-1642-0000' I0515 19:11:40.680187 1661 slave.cpp:3674] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/executors/3659da35-6351-4e38-84c5-f76bb3eca499/runs/09947a0f-892b-4a60-8dc3-63424a50f207/tasks/3659da35-6351-4e38-84c5-f76bb3eca499/task.info' I0515 19:11:40.680425 1661 slave.cpp:1130] Queuing task '3659da35-6351-4e38-84c5-f76bb3eca499' for executor 3659da35-6351-4e38-84c5-f76bb3eca499 of framework '20140515-191140-160088899-45547-1642-0000 I0515 19:11:40.680515 1661 slave.cpp:491] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/executors/3659da35-6351-4e38-84c5-f76bb3eca499/runs/09947a0f-892b-4a60-8dc3-63424a50f207' I0515 19:11:40.683475 1667 launcher.cpp:117] Forked child with pid '2154' for container '09947a0f-892b-4a60-8dc3-63424a50f207' I0515 19:11:40.683593 1667 mesos_containerizer.cpp:746] Checkpointing executor's forked pid 2154 to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/executors/3659da35-6351-4e38-84c5-f76bb3eca499/runs/09947a0f-892b-4a60-8dc3-63424a50f207/pids/forked.pid' I0515 19:11:40.684821 1665 mesos_containerizer.cpp:623] Fetching URIs for container '09947a0f-892b-4a60-8dc3-63424a50f207' using command '/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src/mesos-fetcher' I0515 19:11:40.703064 1662 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 26.641507ms I0515 19:11:40.703152 1662 replica.cpp:676] Persisted action at 4 I0515 19:11:40.704370 1667 replica.cpp:655] Replica received learned notice for position 4 I0515 19:11:40.722848 1667 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 18.367871ms I0515 19:11:40.722893 1667 leveldb.cpp:401] Deleting ~2 keys from leveldb took 19731ns I0515 19:11:40.722903 1667 replica.cpp:676] Persisted action at 4 I0515 19:11:40.722913 1667 replica.cpp:661] Replica learned TRUNCATE action at position 4 I0515 19:11:41.235136 1668 slave.cpp:2302] Monitoring executor '3659da35-6351-4e38-84c5-f76bb3eca499' of framework '20140515-191140-160088899-45547-1642-0000' in container '09947a0f-892b-4a60-8dc3-63424a50f207' WARNING: Logging before InitGoogleLogging() is written to STDERR I0515 19:11:41.275168 2176 process.cpp:1671] libprocess is initialized on 67.195.138.9:55464 for 8 cpus I0515 19:11:41.276181 2176 exec.cpp:131] Version: 0.19.0 I0515 19:11:41.277737 2193 exec.cpp:181] Executor started at: executor(1)@67.195.138.9:55464 with pid 2176 I0515 19:11:41.278373 1665 slave.cpp:1610] Got registration for executor '3659da35-6351-4e38-84c5-f76bb3eca499' of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.278439 1665 slave.cpp:1695] Checkpointing executor pid 'executor(1)@67.195.138.9:55464' to '/tmp/SlaveRecoveryTest_0_RecoverCompletedExecutor_8A1wz1/meta/slaves/20140515-191140-160088899-45547-1642-0/frameworks/20140515-191140-160088899-45547-1642-0000/executors/3659da35-6351-4e38-84c5-f76bb3eca499/runs/09947a0f-892b-4a60-8dc3-63424a50f207/pids/libprocess.pid' I0515 19:11:41.278866 1665 slave.cpp:1729] Flushing queued task 3659da35-6351-4e38-84c5-f76bb3eca499 for executor '3659da35-6351-4e38-84c5-f76bb3eca499' of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.279049 1669 process.cpp:1098] Socket closed while receiving I0515 19:11:41.279211 2191 exec.cpp:205] Executor registered on slave 20140515-191140-160088899-45547-1642-0 I0515 19:11:41.279233 2198 process.cpp:1037] Socket closed while receiving I0515 19:11:41.280128 2191 exec.cpp:217] Executor::registered took 106701ns Registered executor on vesta.apache.org I0515 19:11:41.280304 2191 exec.cpp:292] Executor asked to run task '3659da35-6351-4e38-84c5-f76bb3eca499' I0515 19:11:41.280357 2191 exec.cpp:301] Executor::launchTask took 40460ns Starting task 3659da35-6351-4e38-84c5-f76bb3eca499 Forked command at 2199 sh -c 'exit 0' I0515 19:11:41.281980 2190 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.282326 1664 slave.cpp:1965] Handling status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 from executor(1)@67.195.138.9:55464 I0515 19:11:41.282485 1666 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.282506 1666 status_update_manager.cpp:499] Creating StatusUpdate stream for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.282747 1666 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.444167 1666 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 to master@67.195.138.9:45547 I0515 19:11:41.444340 1664 master.cpp:2483] Status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 from slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) I0515 19:11:41.444373 1668 slave.cpp:2086] Status update manager successfully handled status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.444396 1668 slave.cpp:2092] Sending acknowledgement for status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 to executor(1)@67.195.138.9:55464 I0515 19:11:41.444455 1665 sched.cpp:620] Scheduler::statusUpdate took 17935ns I0515 19:11:41.444571 1669 process.cpp:1098] Socket closed while receiving I0515 19:11:41.444602 1668 status_update_manager.cpp:398] Received status update acknowledgement (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.444627 1668 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.444689 2192 exec.cpp:338] Executor received status update acknowledgement c6c33075-e5ce-4e53-bd44-cb1164ff54e7 for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.444720 2198 process.cpp:1037] Socket closed while receiving I0515 19:11:41.520257 1668 slave.cpp:1550] Status update manager successfully handled status update acknowledgement (UUID: c6c33075-e5ce-4e53-bd44-cb1164ff54e7) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:41.530926 1662 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 43326ns Command exited with status 0 (pid: 2199) I0515 19:11:42.282755 2190 exec.cpp:524] Executor sending status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.283025 1665 slave.cpp:1965] Handling status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 from executor(1)@67.195.138.9:55464 I0515 19:11:42.283097 1665 slave.cpp:3607] Terminating task 3659da35-6351-4e38-84c5-f76bb3eca499 I0515 19:11:42.283318 1663 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.283339 1663 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.384146 1663 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 to master@67.195.138.9:45547 I0515 19:11:42.384321 1668 master.cpp:2483] Status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 from slave 20140515-191140-160088899-45547-1642-0 at slave(64)@67.195.138.9:45547 (vesta.apache.org) I0515 19:11:42.384366 1666 slave.cpp:2086] Status update manager successfully handled status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.384414 1666 slave.cpp:2092] Sending acknowledgement for status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 to executor(1)@67.195.138.9:55464 I0515 19:11:42.384397 1668 master.hpp:653] Removing task 3659da35-6351-4e38-84c5-f76bb3eca499 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) I0515 19:11:42.384479 1662 sched.cpp:620] Scheduler::statusUpdate took 11773ns I0515 19:11:42.384629 1664 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140515-191140-160088899-45547-1642-0 from framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.384712 1669 process.cpp:1098] Socket closed while receiving I0515 19:11:42.384831 1662 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.384877 1662 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_FINISHED (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.384912 2194 exec.cpp:338] Executor received status update acknowledgement 760234eb-547c-49ad-a0c9-57984e5fcb67 for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.385021 2198 process.cpp:1037] Socket closed while receiving I0515 19:11:42.454076 1662 status_update_manager.cpp:530] Cleaning up status update stream for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.454205 1662 slave.cpp:1550] Status update manager successfully handled status update acknowledgement (UUID: 760234eb-547c-49ad-a0c9-57984e5fcb67) for task 3659da35-6351-4e38-84c5-f76bb3eca499 of framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.454234 1662 slave.cpp:3649] Completing task 3659da35-6351-4e38-84c5-f76bb3eca499 I0515 19:11:42.532122 1667 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 to framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.532286 1667 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 256525ns I0515 19:11:42.532357 1663 master.hpp:663] Adding offer 20140515-191140-160088899-45547-1642-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140515-191140-160088899-45547-1642-0 (vesta.apache.org) I0515 19:11:42.532412 1663 master.cpp:2788] Sending 1 offers to framework 20140515-191140-160088899-45547-1642-0000 I0515 19:11:42.532569 1661 sched.cpp:529] Scheduler::resourceOffers took 19163ns I0515 19:11:43.283460 1669 process.cpp:1037] Socket closed while receiving I0515 19:11:43.532954 1664 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 30283ns Build timed out (after 120 minutes). Marking the build as failed. Build was aborted
