See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2473/changes>
Changes: [dhamon] Differentiate between slave and offer ids ------------------------------------------ [...truncated 25823 lines...] I1022 23:49:58.784020 28603 master.cpp:363] Master only allowing authenticated slaves to register I1022 23:49:58.784030 28603 credentials.hpp:36] Loading credentials for authentication from '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_VbLvU8/credentials' I1022 23:49:58.784097 28608 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 1.060798ms I1022 23:49:58.784119 28608 replica.cpp:320] Persisted replica status to STARTING I1022 23:49:58.784139 28603 master.cpp:392] Authorization enabled I1022 23:49:58.784201 28608 recover.cpp:463] Replica is in STARTING status I1022 23:49:58.784397 28608 master.cpp:120] No whitelist given. Advertising offers for all slaves I1022 23:49:58.784747 28611 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : [email protected]:36297 I1022 23:49:58.784898 28613 master.cpp:1242] The newly elected leader is [email protected]:36297 with id 20141022-234958-3142697795-36297-28588 I1022 23:49:58.784914 28613 master.cpp:1255] Elected as the leading master! I1022 23:49:58.784924 28613 master.cpp:1073] Recovering from registrar I1022 23:49:58.784926 28611 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I1022 23:49:58.784993 28613 registrar.cpp:313] Recovering registrar I1022 23:49:58.785223 28611 recover.cpp:188] Received a recover response from a replica in STARTING status I1022 23:49:58.785341 28611 recover.cpp:554] Updating replica status to VOTING I1022 23:49:58.785760 28611 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 333269ns I1022 23:49:58.785778 28611 replica.cpp:320] Persisted replica status to VOTING I1022 23:49:58.785825 28611 recover.cpp:568] Successfully joined the Paxos group I1022 23:49:58.785892 28611 recover.cpp:452] Recover process terminated I1022 23:49:58.786036 28611 log.cpp:656] Attempting to start the writer I1022 23:49:58.786501 28606 replica.cpp:474] Replica received implicit promise request with proposal 1 I1022 23:49:58.786792 28606 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 271018ns I1022 23:49:58.786810 28606 replica.cpp:342] Persisted promised to 1 I1022 23:49:58.787049 28606 coordinator.cpp:230] Coordinator attemping to fill missing position I1022 23:49:58.787730 28610 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I1022 23:49:58.788100 28610 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 347683ns I1022 23:49:58.788116 28610 replica.cpp:676] Persisted action at 0 I1022 23:49:58.788492 28610 replica.cpp:508] Replica received write request for position 0 I1022 23:49:58.788524 28610 leveldb.cpp:438] Reading position from leveldb took 16351ns I1022 23:49:58.788832 28610 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 288220ns I1022 23:49:58.788848 28610 replica.cpp:676] Persisted action at 0 I1022 23:49:58.789029 28610 replica.cpp:655] Replica received learned notice for position 0 I1022 23:49:58.789222 28610 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 176617ns I1022 23:49:58.789238 28610 replica.cpp:676] Persisted action at 0 I1022 23:49:58.789247 28610 replica.cpp:661] Replica learned NOP action at position 0 I1022 23:49:58.789477 28610 log.cpp:672] Writer started with ending position 0 I1022 23:49:58.789831 28610 leveldb.cpp:438] Reading position from leveldb took 11010ns I1022 23:49:58.791254 28610 registrar.cpp:346] Successfully fetched the registry (0B) in 6.239744ms I1022 23:49:58.791309 28610 registrar.cpp:445] Applied 1 operations in 4398ns; attempting to update the 'registry' I1022 23:49:58.792754 28610 log.cpp:680] Attempting to append 139 bytes to the log I1022 23:49:58.792817 28610 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1022 23:49:58.793117 28610 replica.cpp:508] Replica received write request for position 1 I1022 23:49:58.793505 28610 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 368961ns I1022 23:49:58.793524 28610 replica.cpp:676] Persisted action at 1 I1022 23:49:58.793771 28610 replica.cpp:655] Replica received learned notice for position 1 I1022 23:49:58.794075 28610 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 288311ns I1022 23:49:58.794092 28610 replica.cpp:676] Persisted action at 1 I1022 23:49:58.794102 28610 replica.cpp:661] Replica learned APPEND action at position 1 I1022 23:49:58.794467 28610 registrar.cpp:490] Successfully updated the 'registry' in 3.129088ms I1022 23:49:58.794522 28610 registrar.cpp:376] Successfully recovered registrar I1022 23:49:58.794577 28610 log.cpp:699] Attempting to truncate the log to 1 I1022 23:49:58.794663 28610 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register I1022 23:49:58.794705 28610 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1022 23:49:58.794883 28610 replica.cpp:508] Replica received write request for position 2 I1022 23:49:58.795156 28610 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 260060ns I1022 23:49:58.795169 28610 replica.cpp:676] Persisted action at 2 I1022 23:49:58.795477 28617 replica.cpp:655] Replica received learned notice for position 2 I1022 23:49:58.795795 28617 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 298268ns I1022 23:49:59.009078 28617 leveldb.cpp:401] Deleting ~1 keys from leveldb took 62645ns I1022 23:49:59.009115 28617 replica.cpp:676] Persisted action at 2 I1022 23:49:59.009127 28617 replica.cpp:661] Replica learned TRUNCATE action at position 2 I1022 23:49:59.019134 28616 slave.cpp:169] Slave started on 92)@67.195.81.187:36297 I1022 23:49:59.019175 28616 credentials.hpp:84] Loading credential for authentication from '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/credential' I1022 23:49:59.019275 28616 slave.cpp:276] Slave using credential for: test-principal I1022 23:49:59.019410 28616 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1022 23:49:59.019479 28616 slave.cpp:318] Slave hostname: pomona.apache.org I1022 23:49:59.019490 28616 slave.cpp:319] Slave checkpoint: false I1022 23:49:59.019891 28606 state.cpp:33] Recovering state from '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/meta' I1022 23:49:59.020009 28606 status_update_manager.cpp:197] Recovering status update manager I1022 23:49:59.020110 28606 slave.cpp:3437] Finished recovery I1022 23:49:59.020411 28606 slave.cpp:597] New master detected at [email protected]:36297 I1022 23:49:59.020434 28606 slave.cpp:660] Authenticating with master [email protected]:36297 I1022 23:49:59.020488 28606 slave.cpp:633] Detecting new master I1022 23:49:59.020531 28606 status_update_manager.cpp:171] Pausing sending status updates I1022 23:49:59.020570 28606 authenticatee.hpp:133] Creating new client SASL connection I1022 23:49:59.020679 28606 master.cpp:3847] Authenticating slave(92)@67.195.81.187:36297 I1022 23:49:59.020791 28606 authenticator.hpp:161] Creating new server SASL connection I1022 23:49:59.020864 28606 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1022 23:49:59.020884 28606 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1022 23:49:59.020989 28617 authenticator.hpp:267] Received SASL authentication start I1022 23:49:59.021031 28617 authenticator.hpp:389] Authentication requires more steps I1022 23:49:59.021119 28617 authenticatee.hpp:270] Received SASL authentication step I1022 23:49:59.021214 28617 authenticator.hpp:295] Received SASL authentication step I1022 23:49:59.021236 28617 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1022 23:49:59.021247 28617 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1022 23:49:59.021262 28617 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1022 23:49:59.021275 28617 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1022 23:49:59.021292 28617 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1022 23:49:59.021301 28617 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1022 23:49:59.021317 28617 authenticator.hpp:381] Authentication success I1022 23:49:59.021363 28606 authenticatee.hpp:310] Authentication success I1022 23:49:59.021374 28617 master.cpp:3887] Successfully authenticated principal 'test-principal' at slave(92)@67.195.81.187:36297 I1022 23:49:59.021438 28606 slave.cpp:717] Successfully authenticated with master [email protected]:36297 I1022 23:49:59.021492 28606 slave.cpp:1045] Will retry registration in 942597ns if necessary I1022 23:49:59.021574 28606 master.cpp:3026] Registering slave at slave(92)@67.195.81.187:36297 (pomona.apache.org) with id 20141022-234958-3142697795-36297-28588-S0 I1022 23:49:59.021716 28606 registrar.cpp:445] Applied 1 operations in 14399ns; attempting to update the 'registry' I1022 23:49:59.022148 28588 sched.cpp:137] Version: 0.21.0 I1022 23:49:59.022495 28605 sched.cpp:233] New master detected at [email protected]:36297 I1022 23:49:59.022516 28605 sched.cpp:283] Authenticating with master [email protected]:36297 I1022 23:49:59.022589 28608 authenticatee.hpp:133] Creating new client SASL connection I1022 23:49:59.022703 28604 slave.cpp:1045] Will retry registration in 5.737624ms if necessary I1022 23:49:59.022712 28608 master.cpp:3847] Authenticating [email protected]:36297 I1022 23:49:59.022814 28611 authenticator.hpp:161] Creating new server SASL connection I1022 23:49:59.022835 28608 master.cpp:3014] Ignoring register slave message from slave(92)@67.195.81.187:36297 (pomona.apache.org) as admission is already in progress I1022 23:49:59.022878 28608 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1022 23:49:59.022894 28608 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1022 23:49:59.022933 28608 authenticator.hpp:267] Received SASL authentication start I1022 23:49:59.022969 28608 authenticator.hpp:389] Authentication requires more steps I1022 23:49:59.023084 28602 authenticatee.hpp:270] Received SASL authentication step I1022 23:49:59.023161 28612 authenticator.hpp:295] Received SASL authentication step I1022 23:49:59.023182 28612 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1022 23:49:59.023185 28613 log.cpp:680] Attempting to append 316 bytes to the log I1022 23:49:59.023191 28612 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1022 23:49:59.023203 28612 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1022 23:49:59.023214 28612 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1022 23:49:59.023222 28612 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1022 23:49:59.023228 28612 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1022 23:49:59.023241 28612 authenticator.hpp:381] Authentication success I1022 23:49:59.023252 28611 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1022 23:49:59.023316 28602 master.cpp:3887] Successfully authenticated principal 'test-principal' at [email protected]:36297 I1022 23:49:59.023345 28603 authenticatee.hpp:310] Authentication success I1022 23:49:59.023476 28612 sched.cpp:357] Successfully authenticated with master [email protected]:36297 I1022 23:49:59.023494 28612 sched.cpp:476] Sending registration request to [email protected]:36297 I1022 23:49:59.023669 28607 replica.cpp:508] Replica received write request for position 3 I1022 23:49:59.023797 28605 master.cpp:1362] Received registration request for framework 'default' at [email protected]:36297 I1022 23:49:59.023816 28605 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*' I1022 23:49:59.023967 28614 master.cpp:1426] Registering framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:49:59.024065 28613 hierarchical_allocator_process.hpp:329] Added framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.024082 28613 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1022 23:49:59.024091 28613 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 9093ns I1022 23:49:59.024139 28613 sched.cpp:407] Framework registered with 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.137439 28613 sched.cpp:421] Scheduler::registered took 63837ns I1022 23:49:59.029038 28606 slave.cpp:1045] Will retry registration in 28.855729ms if necessary I1022 23:49:59.024247 28607 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 560041ns I1022 23:49:59.029153 28605 master.cpp:3014] Ignoring register slave message from slave(92)@67.195.81.187:36297 (pomona.apache.org) as admission is already in progress I1022 23:49:59.137543 28607 replica.cpp:676] Persisted action at 3 I1022 23:49:59.138083 28606 replica.cpp:655] Replica received learned notice for position 3 I1022 23:49:59.138620 28606 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 517056ns I1022 23:49:59.138638 28606 replica.cpp:676] Persisted action at 3 I1022 23:49:59.138649 28606 replica.cpp:661] Replica learned APPEND action at position 3 I1022 23:49:59.139158 28613 registrar.cpp:490] Successfully updated the 'registry' in 117.417216ms I1022 23:49:59.139292 28611 log.cpp:699] Attempting to truncate the log to 3 I1022 23:49:59.139355 28603 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1022 23:49:59.139505 28615 master.cpp:3080] Registered slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@67.195.81.187:36297 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1022 23:49:59.139513 28611 hierarchical_allocator_process.hpp:442] Added slave 20141022-234958-3142697795-36297-28588-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I1022 23:49:59.139598 28611 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141022-234958-3142697795-36297-28588-S0 to framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.139669 28604 slave.cpp:2517] Received ping from slave-observer(89)@67.195.81.187:36297 I1022 23:49:59.139720 28607 replica.cpp:508] Replica received write request for position 4 I1022 23:49:59.139740 28604 slave.cpp:751] Registered with master [email protected]:36297; given slave ID 20141022-234958-3142697795-36297-28588-S0 I1022 23:49:59.139801 28611 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141022-234958-3142697795-36297-28588-S0 in 235887ns I1022 23:49:59.139806 28613 status_update_manager.cpp:178] Resuming sending status updates I1022 23:49:59.139919 28617 master.cpp:3789] Sending 1 offers to framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:49:59.140096 28607 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 350458ns I1022 23:49:59.140111 28607 replica.cpp:676] Persisted action at 4 I1022 23:49:59.140264 28617 sched.cpp:544] Scheduler::resourceOffers took 182145ns I1022 23:49:59.140290 28607 replica.cpp:655] Replica received learned notice for position 4 I1022 23:49:59.140535 28617 master.cpp:2315] Processing reply for offers: [ 20141022-234958-3142697795-36297-28588-O0 ] on slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@67.195.81.187:36297 (pomona.apache.org) for framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:49:59.140576 28607 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 271109ns W1022 23:49:59.140578 28617 master.cpp:1969] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W1022 23:49:59.140604 28617 master.cpp:1980] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I1022 23:49:59.140612 28607 leveldb.cpp:401] Deleting ~2 keys from leveldb took 19045ns I1022 23:49:59.140627 28607 replica.cpp:676] Persisted action at 4 I1022 23:49:59.140632 28617 master.cpp:2411] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' I1022 23:49:59.140637 28607 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1022 23:49:59.140949 28617 master.hpp:877] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20141022-234958-3142697795-36297-28588-S0 (pomona.apache.org) I1022 23:49:59.140985 28617 master.cpp:2474] Launching task 0 of framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 with resources cpus(*):1; mem(*):512 on slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@67.195.81.187:36297 (pomona.apache.org) I1022 23:49:59.141108 28604 slave.cpp:1076] Got assigned task 0 for framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.141242 28609 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]) on slave 20141022-234958-3142697795-36297-28588-S0 from framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.141288 28609 hierarchical_allocator_process.hpp:599] Framework 20141022-234958-3142697795-36297-28588-0000 filtered slave 20141022-234958-3142697795-36297-28588-S0 for 5secs I1022 23:49:59.141373 28604 slave.cpp:1186] Launching task 0 for framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.142989 28604 slave.cpp:3852] Launching executor default of framework 20141022-234958-3142697795-36297-28588-0000 in work directory '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/slaves/20141022-234958-3142697795-36297-28588-S0/frameworks/20141022-234958-3142697795-36297-28588-0000/executors/default/runs/ab333897-e649-4960-8580-9dcff92b63ec' I1022 23:49:59.144456 28604 exec.cpp:132] Version: 0.21.0 I1022 23:49:59.144541 28617 exec.cpp:182] Executor started at: executor(34)@67.195.81.187:36297 with pid 28588 I1022 23:49:59.144598 28604 slave.cpp:1312] Queuing task '0' for executor default of framework '20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.144649 28604 slave.cpp:550] Successfully attached file '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/slaves/20141022-234958-3142697795-36297-28588-S0/frameworks/20141022-234958-3142697795-36297-28588-0000/executors/default/runs/ab333897-e649-4960-8580-9dcff92b63ec' I1022 23:49:59.144696 28604 slave.cpp:2783] Monitoring executor 'default' of framework '20141022-234958-3142697795-36297-28588-0000' in container 'ab333897-e649-4960-8580-9dcff92b63ec' I1022 23:49:59.144783 28604 slave.cpp:1844] Got registration for executor 'default' of framework 20141022-234958-3142697795-36297-28588-0000 from executor(34)@67.195.81.187:36297 I1022 23:49:59.144930 28604 slave.cpp:1963] Flushing queued task 0 for executor 'default' of framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.144966 28617 exec.cpp:206] Executor registered on slave 20141022-234958-3142697795-36297-28588-S0 I1022 23:49:59.145961 28617 exec.cpp:218] Executor::registered took 15657ns I1022 23:49:59.146023 28617 exec.cpp:293] Executor asked to run task '0' I1022 23:49:59.146060 28617 exec.cpp:302] Executor::launchTask took 24526ns I1022 23:49:59.146951 28617 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:49:59.147037 28617 slave.cpp:2197] Handling status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 from executor(34)@67.195.81.187:36297 I1022 23:49:59.147059 28617 slave.cpp:4160] Terminating task 0 I../../src/tests/reconciliation_tests.cpp:720: Failure Failed to wait 10secs for update1 ../../src/tests/reconciliation_tests.cpp:703: Failure Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))... Expected: to be called once 1022 23:49:59.147155 28617 status_update_manager.cpp:317] Received status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 Actual: never called - unsatisfied and active I1022 23:50:09.380831 28617 status_update_manager.cpp:494] Creating StatusUpdate stream for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:03.785439 28613 master.cpp:120] No whitelist given. Advertising offers for all slaves I1022 23:50:09.380949 28617 status_update_manager.cpp:371] Forwarding update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 to the slave I1022 23:50:09.380975 28606 master.cpp:768] Framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 disconnected I1022 23:49:59.785217 28602 hierarchical_allocator_process.hpp:816] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20141022-234958-3142697795-36297-28588-S0 for framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:09.380996 28606 master.cpp:1731] Disconnecting framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:50:09.381009 28606 master.cpp:1747] Deactivating framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:50:09.381032 28606 master.cpp:790] Giving framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 0ns to failover I1022 23:50:09.381029 28602 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 9.59591129secs I1022 23:50:09.381116 28602 hierarchical_allocator_process.hpp:405] Deactivated framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:09.381554 28606 slave.cpp:2437] Forwarding the update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 to [email protected]:36297 I1022 23:50:09.381731 28615 master.cpp:3659] Framework failover timeout, removing framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 I1022 23:50:09.381752 28615 master.cpp:4195] Removing framework 20141022-234958-3142697795-36297-28588-0000 (default) at [email protected]:36297 W1022 23:50:09.381784 28615 master.cpp:4636] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20141022-234958-3142697795-36297-28588-0000 on slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@67.195.81.187:36297 (pomona.apache.org) in non-terminal state TASK_STAGING I1022 23:50:09.381868 28606 slave.cpp:2364] Status update manager successfully handled status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:09.381885 28606 slave.cpp:2370] Sending acknowledgement for status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 to executor(34)@67.195.81.187:36297 I1022 23:50:09.381944 28606 slave.cpp:1517] Asked to shut down framework 20141022-234958-3142697795-36297-28588-0000 by [email protected]:36297 I1022 23:50:09.381959 28606 slave.cpp:1542] Shutting down framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:09.381976 28606 slave.cpp:3117] Shutting down executor 'default' of framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:09.382115 28607 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141022-234958-3142697795-36297-28588-S0 from framework 20141022-234958-3142697795-36297-28588-0000 F1022 23:50:10.381491 28602 logging.cpp:57] RAW: Pure virtual method called I1022 23:50:09.382222 28615 master.cpp:4679] Removing executor 'default' with resources of framework 20141022-234958-3142697795-36297-28588-0000 on slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@67.195.81.187:36297 (pomona.apache.org) I1022 23:50:10.381491 28613 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 30737ns I1022 23:50:12.877471 28617 hierarchical_allocator_process.hpp:360] Removed framework 20141022-234958-3142697795-36297-28588-0000 I1022 23:50:12.877516 28615 master.cpp:677] Master terminating I1022 23:50:12.877804 28608 slave.cpp:2602] [email protected]:36297 exited W1022 23:50:12.877830 28608 slave.cpp:2605] Master disconnected! Waiting for a new master to be elected F1022 23:50:12.877830 28588 logging.cpp:57] RAW: Pure virtual method called @ 0x2b89187e25dd google::LogMessage::Fail() @ 0x2b89187e9cd6 google::RawLog__() @ 0x2b89183f84d9 mesos::internal::slave::ResourceMonitorProcess::collect() @ 0x2b89187a439a process::ProcessManager::resume() @ 0x2b89187e25dd google::LogMessage::Fail() @ 0x2b89187a465c process::schedule() @ 0x2b89187e9cd6 google::RawLog__() @ 0x507226 mesos::internal::tests::Cluster::Slaves::shutdown() @ 0x7a7f24 mesos::internal::tests::MesosTest::ShutdownSlaves() @ 0x9a4713 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x99b980 testing::Test::Run() @ 0x99ba5e testing::TestInfo::Run() @ 0x99bb65 testing::TestCase::Run() @ 0x99be08 testing::internal::UnitTestImpl::RunAllTests() @ 0x99c0a7 testing::UnitTest::Run() @ 0x490aca main @ 0x2b891a707ec5 (unknown) @ 0x49dfa8 (unknown) make[3]: *** [check-local] Aborted make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> make[2]: *** [check-am] Error 2 make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> make: *** [check-recursive] Error 1 Test finished Exit status: 2 Build step 'Execute shell' marked build as failure Recording test results
