MasterTest.RecoverResources is flaky: https://issues.apache.org/jira/browse/MESOS-2003
-- Jiang Yan Xu <y...@jxu.me> @xujyan <http://twitter.com/xujyan> On Mon, Oct 27, 2014 at 7:41 PM, Apache Jenkins Server < jenk...@builds.apache.org> wrote: > See < > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2221/changes > > > > Changes: > > [tnachen] Added support for both 1.8 and earlier versions of svn library. > > ------------------------------------------ > [...truncated 14964 lines...] > I1028 02:38:04.510162 11893 log.cpp:680] Attempting to append 139 bytes to > the log > I1028 02:38:04.510406 11889 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I1028 02:38:04.511181 11889 replica.cpp:508] Replica received write > request for position 1 > I1028 02:38:04.511767 11889 leveldb.cpp:343] Persisting action (158 bytes) > to leveldb took 550337ns > I1028 02:38:04.511792 11889 replica.cpp:676] Persisted action at 1 > I1028 02:38:04.512370 11889 replica.cpp:655] Replica received learned > notice for position 1 > I1028 02:38:04.512802 11889 leveldb.cpp:343] Persisting action (160 bytes) > to leveldb took 411874ns > I1028 02:38:04.512821 11889 replica.cpp:676] Persisted action at 1 > I1028 02:38:04.512841 11889 replica.cpp:661] Replica learned APPEND action > at position 1 > I1028 02:38:04.513649 11895 registrar.cpp:490] Successfully updated the > 'registry' in 6.086144ms > I1028 02:38:04.513772 11895 registrar.cpp:376] Successfully recovered > registrar > I1028 02:38:04.513991 11891 log.cpp:699] Attempting to truncate the log to > 1 > I1028 02:38:04.514045 11895 master.cpp:1100] Recovered 0 slaves from the > Registry (101B) ; allowing 10mins for slaves to re-register > I1028 02:38:04.514138 11889 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I1028 02:38:04.514847 11898 replica.cpp:508] Replica received write > request for position 2 > I1028 02:38:04.515223 11898 leveldb.cpp:343] Persisting action (16 bytes) > to leveldb took 349767ns > I1028 02:38:04.515239 11898 replica.cpp:676] Persisted action at 2 > I1028 02:38:04.515666 11898 replica.cpp:655] Replica received learned > notice for position 2 > I1028 02:38:04.516059 11898 leveldb.cpp:343] Persisting action (18 bytes) > to leveldb took 377837ns > I1028 02:38:04.516091 11898 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 16661ns > I1028 02:38:04.516103 11898 replica.cpp:676] Persisted action at 2 > I1028 02:38:04.516118 11898 replica.cpp:661] Replica learned TRUNCATE > action at position 2 > I1028 02:38:04.528028 11893 slave.cpp:169] Slave started on 28)@ > 67.195.81.187:39931 > I1028 02:38:04.528062 11893 credentials.hpp:84] Loading credential for > authentication from '/tmp/MasterTest_RecoverResources_vPPbEB/credential' > I1028 02:38:04.528213 11893 slave.cpp:276] Slave using credential for: > test-principal > I1028 02:38:04.528563 11893 slave.cpp:289] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] > I1028 02:38:04.528663 11893 slave.cpp:318] Slave hostname: > pomona.apache.org > I1028 02:38:04.528677 11893 slave.cpp:319] Slave checkpoint: false > W1028 02:38:04.528684 11893 slave.cpp:321] Disabling checkpointing is > deprecated and the --checkpoint flag will be removed in a future release. > Please avoid using this flag > I1028 02:38:04.529392 11892 state.cpp:33] Recovering state from > '/tmp/MasterTest_RecoverResources_vPPbEB/meta' > I1028 02:38:04.532413 11875 sched.cpp:137] Version: 0.21.0 > I1028 02:38:05.495925 11903 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I1028 02:38:09.495995 11899 master.cpp:120] No whitelist given. > Advertising offers for all slaves > I1028 02:38:13.648022 11903 hierarchical_allocator_process.hpp:659] > Performed allocation for 0 slaves in 8.152112733secs > I1028 02:38:13.648339 11903 status_update_manager.cpp:197] Recovering > status update manager > I1028 02:38:13.648790 11903 sched.cpp:233] New master detected at > master@67.195.81.187:39931 > I1028 02:38:13.648816 11903 sched.cpp:283] Authenticating with master > master@67.195.81.187:39931 > I1028 02:38:13.648828 11900 slave.cpp:3456] Finished recovery > I1028 02:38:13.649049 11894 authenticatee.hpp:133] Creating new client > SASL connection > I1028 02:38:13.649325 11901 master.cpp:3853] Authenticating > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:13.649443 11893 status_update_manager.cpp:171] Pausing sending > status updates > I1028 02:38:13.649458 11896 slave.cpp:602] New master detected at > master@67.195.81.187:39931 > I1028 02:38:13.649487 11896 slave.cpp:665] Authenticating with master > master@67.195.81.187:39931 > I1028 02:38:13.649515 11894 authenticator.hpp:161] Creating new server > SASL connection > I1028 02:38:13.649595 11896 slave.cpp:638] Detecting new master > I1028 02:38:13.649634 11897 authenticatee.hpp:133] Creating new client > SASL connection > I1028 02:38:13.649688 11898 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 02:38:13.649723 11898 authenticatee.hpp:250] Attempting to > authenticate with mechanism 'CRAM-MD5' > I1028 02:38:13.649793 11903 master.cpp:3853] Authenticating slave(28)@ > 67.195.81.187:39931 > I1028 02:38:13.649809 11896 authenticator.hpp:267] Received SASL > authentication start > I1028 02:38:13.649863 11896 authenticator.hpp:389] Authentication requires > more steps > I1028 02:38:13.649957 11900 authenticatee.hpp:270] Received SASL > authentication step > I1028 02:38:13.649961 11898 authenticator.hpp:161] Creating new server > SASL connection > I1028 02:38:13.650054 11900 authenticator.hpp:295] Received SASL > authentication step > I1028 02:38:13.650084 11900 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 > I1028 02:38:13.650100 11900 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 02:38:13.650142 11897 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 02:38:13.650187 11897 authenticatee.hpp:250] Attempting to > authenticate with mechanism 'CRAM-MD5' > I1028 02:38:13.650151 11900 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 02:38:13.650265 11900 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 > I1028 02:38:13.650357 11900 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1028 02:38:13.650364 11900 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1028 02:38:13.650387 11900 authenticator.hpp:381] Authentication success > I1028 02:38:13.650293 11897 authenticator.hpp:267] Received SASL > authentication start > I1028 02:38:13.650456 11897 authenticator.hpp:389] Authentication requires > more steps > I1028 02:38:13.650511 11898 authenticatee.hpp:310] Authentication success > I1028 02:38:13.650609 11904 authenticatee.hpp:270] Received SASL > authentication step > I1028 02:38:13.650616 11900 master.cpp:3893] Successfully authenticated > principal 'test-principal' at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:13.650682 11904 authenticator.hpp:295] Received SASL > authentication step > I1028 02:38:13.650714 11904 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 > I1028 02:38:13.650732 11904 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 02:38:13.650774 11904 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 02:38:13.650805 11904 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 > I1028 02:38:13.650820 11904 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1028 02:38:13.650831 11904 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1028 02:38:13.650851 11904 authenticator.hpp:381] Authentication success > I1028 02:38:13.650931 11894 authenticatee.hpp:310] Authentication success > I1028 02:38:13.650926 11896 sched.cpp:357] Successfully authenticated with > master master@67.195.81.187:39931 > I1028 02:38:13.650966 11896 sched.cpp:476] Sending registration request to > master@67.195.81.187:39931 > I1028 02:38:13.650967 11899 master.cpp:3893] Successfully authenticated > principal 'test-principal' at slave(28)@67.195.81.187:39931 > I1028 02:38:13.651166 11897 slave.cpp:722] Successfully authenticated with > master master@67.195.81.187:39931 > I1028 02:38:13.651206 11899 master.cpp:1362] Received registration request > for framework 'default' at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:13.651298 11899 master.cpp:1321] Authorizing framework > principal 'test-principal' to receive offers for role '*' > I1028 02:38:13.651316 11897 slave.cpp:1050] Will retry registration in > 1.610177ms if necessary > I1028 02:38:13.651870 11899 master.cpp:3032] Registering slave at > slave(28)@67.195.81.187:39931 (pomona.apache.org) with id > 20141028-023804-3142697795-39931-11875-S0 > I1028 02:38:13.652227 11899 master.cpp:1426] Registering framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:13.652349 11904 registrar.cpp:445] Applied 1 operations in > 87188ns; attempting to update the 'registry' > I1028 02:38:13.652542 11891 hierarchical_allocator_process.hpp:329] Added > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:13.652564 11891 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I1028 02:38:13.652572 11891 hierarchical_allocator_process.hpp:659] > Performed allocation for 0 slaves in 13012ns > I1028 02:38:13.652673 11892 sched.cpp:407] Framework registered with > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:13.652714 11892 sched.cpp:421] Scheduler::registered took > 20560ns > I1028 02:38:13.653688 11891 slave.cpp:1050] Will retry registration in > 26.064716ms if necessary > I1028 02:38:13.653826 11889 master.cpp:3020] Ignoring register slave > message from slave(28)@67.195.81.187:39931 (pomona.apache.org) as > admission is already in progress > I1028 02:38:13.655606 11902 log.cpp:680] Attempting to append 318 bytes to > the log > I1028 02:38:13.655783 11891 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I1028 02:38:13.656572 11889 replica.cpp:508] Replica received write > request for position 3 > I1028 02:38:13.656903 11889 leveldb.cpp:343] Persisting action (337 bytes) > to leveldb took 297428ns > I1028 02:38:13.656929 11889 replica.cpp:676] Persisted action at 3 > I1028 02:38:13.657467 11899 replica.cpp:655] Replica received learned > notice for position 3 > I1028 02:38:13.658213 11899 leveldb.cpp:343] Persisting action (339 bytes) > to leveldb took 720488ns > I1028 02:38:13.658237 11899 replica.cpp:676] Persisted action at 3 > I1028 02:38:13.658262 11899 replica.cpp:661] Replica learned APPEND action > at position 3 > I1028 02:38:13.680084 11897 slave.cpp:1050] Will retry registration in > 64.496922ms if necessary > I1028 02:38:13.680219 11904 master.cpp:3020] Ignoring register slave > message from slave(28)@67.195.81.187:39931 (pomona.apache.org) as > admission is already in progress > I1028 02:38:14.648702 11898 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I1028 02:38:18.649222 11895 master.cpp:120] No whitelist given. > Advertising offers for all slaves > I1028 02:38:19.073879 11898 hierarchical_allocator_process.hpp:659] > Performed allocation for 0 slaves in 4.425188279secs > I1028 02:38:19.075243 11901 registrar.cpp:490] Successfully updated the > 'registry' in 5.422822144secs > I1028 02:38:19.075714 11899 log.cpp:699] Attempting to truncate the log to > 3 > I1028 02:38:19.075899 11898 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I1028 02:38:19.076500 11897 master.cpp:3086] Registered slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[1-10, 20-30] > I1028 02:38:19.076617 11890 slave.cpp:2522] Received ping from > slave-observer(30)@67.195.81.187:39931 > I1028 02:38:19.076676 11896 hierarchical_allocator_process.hpp:442] Added > slave 20141028-023804-3142697795-39931-11875-S0 (pomona.apache.org) with > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] (and > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] available) > I1028 02:38:19.076746 11890 slave.cpp:756] Registered with master > master@67.195.81.187:39931; given slave ID > 20141028-023804-3142697795-39931-11875-S0 > I1028 02:38:19.076867 11892 status_update_manager.cpp:178] Resuming > sending status updates > I1028 02:38:19.076930 11896 hierarchical_allocator_process.hpp:734] > Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] on > slave 20141028-023804-3142697795-39931-11875-S0 to framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.077153 11895 replica.cpp:508] Replica received write > request for position 4 > I1028 02:38:19.077503 11896 hierarchical_allocator_process.hpp:679] > Performed allocation for slave 20141028-023804-3142697795-39931-11875-S0 in > 739782ns > I1028 02:38:19.077662 11895 leveldb.cpp:343] Persisting action (16 bytes) > to leveldb took 477107ns > I1028 02:38:19.077687 11895 replica.cpp:676] Persisted action at 4 > I1028 02:38:19.077909 11904 master.cpp:3795] Sending 1 offers to framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:19.078209 11889 replica.cpp:655] Replica received learned > notice for position 4 > I1028 02:38:19.078366 11890 sched.cpp:544] Scheduler::resourceOffers took > 83920ns > I1028 02:38:19.078709 11889 leveldb.cpp:343] Persisting action (18 bytes) > to leveldb took 477172ns > I1028 02:38:19.078771 11889 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 38131ns > I1028 02:38:19.078789 11889 replica.cpp:676] Persisted action at 4 > I1028 02:38:19.078812 11889 replica.cpp:661] Replica learned TRUNCATE > action at position 4 > I1028 02:38:19.080180 11895 master.cpp:2321] Processing reply for offers: > [ 20141028-023804-3142697795-39931-11875-O0 ] on slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) for framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:19.080445 11895 master.cpp:2417] Authorizing framework > principal 'test-principal' to launch task 1 as user 'jenkins' > I1028 02:38:19.081792 11895 master.hpp:877] Adding task 1 with resources > cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] > on slave 20141028-023804-3142697795-39931-11875-S0 (pomona.apache.org) > I1028 02:38:19.081954 11895 master.cpp:2480] Launching task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 with > resources cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, > 20-22, 26-30] on slave 20141028-023804-3142697795-39931-11875-S0 at > slave(28)@67.195.81.187:39931 (pomona.apache.org) > I1028 02:38:19.082350 11897 slave.cpp:1081] Got assigned task 1 for > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.083044 11897 slave.cpp:1191] Launching task 1 for framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.085844 11897 slave.cpp:3871] Launching executor default of > framework 20141028-023804-3142697795-39931-11875-0000 in work directory > '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7' > I1028 02:38:19.088114 11897 exec.cpp:132] Version: 0.21.0 > I1028 02:38:19.088326 11889 exec.cpp:182] Executor started at: > executor(11)@67.195.81.187:39931 with pid 11875 > I1028 02:38:19.088418 11897 slave.cpp:1317] Queuing task '1' for executor > default of framework '20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.088522 11897 slave.cpp:555] Successfully attached file > '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7' > I1028 02:38:19.088574 11897 slave.cpp:1849] Got registration for executor > 'default' of framework 20141028-023804-3142697795-39931-11875-0000 from > executor(11)@67.195.81.187:39931 > I1028 02:38:19.088897 11897 slave.cpp:1968] Flushing queued task 1 for > executor 'default' of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.088979 11893 exec.cpp:206] Executor registered on slave > 20141028-023804-3142697795-39931-11875-S0 > I1028 02:38:19.089085 11897 slave.cpp:2802] Monitoring executor 'default' > of framework '20141028-023804-3142697795-39931-11875-0000' in container > 'b2955790-a58e-4fba-bc7f-2e851c9b88d7' > I1028 02:38:19.090515 11893 exec.cpp:218] Executor::registered took 28546ns > I1028 02:38:19.090698 11893 exec.cpp:293] Executor asked to run task '1' > I1028 02:38:19.090760 11893 exec.cpp:302] Executor::launchTask took 44937ns > I1028 02:38:19.093014 11893 exec.cpp:525] Executor sending status update > TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.093221 11893 slave.cpp:2202] Handling status update > TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 from executor(11)@ > 67.195.81.187:39931 > I1028 02:38:19.093544 11896 status_update_manager.cpp:317] Received status > update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 > of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.093583 11896 status_update_manager.cpp:494] Creating > StatusUpdate stream for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.093793 11896 status_update_manager.cpp:371] Forwarding > update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 > of framework 20141028-023804-3142697795-39931-11875-0000 to the slave > I1028 02:38:19.093969 11889 slave.cpp:2442] Forwarding the update > TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 to > master@67.195.81.187:39931 > I1028 02:38:19.094104 11889 slave.cpp:2369] Status update manager > successfully handled status update TASK_RUNNING (UUID: > c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:19.094131 11889 slave.cpp:2375] Sending acknowledgement for > status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to > executor(11)@67.195.81.187:39931 > I1028 02:38:19.094238 11890 master.cpp:3410] Forwarding status update > TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:20.075256 11899 hierarchical_allocator_process.hpp:659] > Performed allocation for 1 slaves in 158229ns > I1028 02:38:22.352753 11889 exec.cpp:339] Executor received status update > acknowledgement c1c3fead-3939-4a31-a474-58c5e3078c80 for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.352778 11890 master.cpp:3382] Status update TASK_RUNNING > (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 from slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) > I1028 02:38:22.352833 11890 master.cpp:4617] Updating the latest state of > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to > TASK_RUNNING > I1028 02:38:22.352912 11900 sched.cpp:635] Scheduler::statusUpdate took > 52537ns > I1028 02:38:22.353186 11894 master.cpp:2882] Forwarding status update > acknowledgement c1c3fead-3939-4a31-a474-58c5e3078c80 for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 to > slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@ > 67.195.81.187:39931 (pomona.apache.org) > I1028 02:38:22.353481 11894 master.cpp:2683] Asked to kill task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.353530 11891 status_update_manager.cpp:389] Received status > update acknowledgement (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.353579 11894 master.cpp:2778] Telling slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) to kill task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:22.353713 11898 slave.cpp:1373] Asked to kill task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.353994 11898 slave.cpp:1789] Status update manager > successfully handled status update acknowledgement (UUID: > c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.354019 11894 exec.cpp:313] Executor asked to kill task '1' > I1028 02:38:22.354121 11894 exec.cpp:322] Executor::killTask took 77148ns > I1028 02:38:22.356482 11894 exec.cpp:525] Executor sending status update > TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.356678 11889 slave.cpp:2202] Handling status update > TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 from executor(11)@ > 67.195.81.187:39931 > I1028 02:38:22.356757 11889 slave.cpp:4179] Terminating task 1 > I1028 02:38:22.357367 11894 status_update_manager.cpp:317] Received status > update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 > of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.357496 11894 status_update_manager.cpp:371] Forwarding > update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 > of framework 20141028-023804-3142697795-39931-11875-0000 to the slave > I1028 02:38:22.357637 11890 slave.cpp:2442] Forwarding the update > TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 to > master@67.195.81.187:39931 > I1028 02:38:22.357755 11890 slave.cpp:2369] Status update manager > successfully handled status update TASK_KILLED (UUID: > cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.357785 11890 slave.cpp:2375] Sending acknowledgement for > status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to > executor(11)@67.195.81.187:39931 > I1028 02:38:22.357969 11904 exec.cpp:339] Executor received status update > acknowledgement cb28dd88-bdb0-4d16-b4bc-977fcf018b2f for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.357972 11899 master.cpp:3410] Forwarding status update > TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.358099 11899 master.cpp:3382] Status update TASK_KILLED > (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 from slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) > I1028 02:38:22.358144 11899 master.cpp:4617] Updating the latest state of > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to > TASK_KILLED > I1028 02:38:22.358268 11890 sched.cpp:635] Scheduler::statusUpdate took > 60378ns > I1028 02:38:22.358825 11893 hierarchical_allocator_process.hpp:563] > Recovered cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, > 20-22, 26-30] (total allocatable: cpus(*):1.7; mem(*):824; disk(*):1024; > ports(*):[1-4, 9-10, 20-22, 26-30]) on slave > 20141028-023804-3142697795-39931-11875-S0 from framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.358850 11899 master.cpp:4676] Removing task 1 with > resources cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, > 20-22, 26-30] of framework 20141028-023804-3142697795-39931-11875-0000 on > slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@ > 67.195.81.187:39931 (pomona.apache.org) > I1028 02:38:22.358989 11899 master.cpp:2882] Forwarding status update > acknowledgement cb28dd88-bdb0-4d16-b4bc-977fcf018b2f for task 1 of > framework 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 to > slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@ > 67.195.81.187:39931 (pomona.apache.org) > I1028 02:38:22.359190 11899 master.cpp:2671] Reviving offers for framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:22.359256 11896 status_update_manager.cpp:389] Received status > update acknowledgement (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for > task 1 of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.359347 11896 status_update_manager.cpp:525] Cleaning up > status update stream for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.359354 11900 hierarchical_allocator_process.hpp:632] > Removed filters for framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.359622 11890 slave.cpp:1789] Status update manager > successfully handled status update acknowledgement (UUID: > cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.359602 11900 hierarchical_allocator_process.hpp:734] > Offering cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, > 26-30] on slave 20141028-023804-3142697795-39931-11875-S0 to framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:22.359665 11890 slave.cpp:4218] Completing task 1 > I1028 02:38:22.360123 11900 hierarchical_allocator_process.hpp:659] > Performed allocation for 1 slaves in 732112ns > I1028 02:38:22.360455 11903 master.cpp:3795] Sending 1 offers to framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:22.360826 11896 sched.cpp:544] Scheduler::resourceOffers took > 61664ns > I1028 02:38:22.361403 11903 slave.cpp:2860] Executor 'default' of > framework 20141028-023804-3142697795-39931-11875-0000 exited with status 0 > I1028 02:38:22.361948 11900 master.cpp:2321] Processing reply for offers: > [ 20141028-023804-3142697795-39931-11875-O1 ] on slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) for framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:23.353077 11893 hierarchical_allocator_process.hpp:659] > Performed allocation for 1 slaves in 168599ns > I1028 02:38:24.074503 11899 master.cpp:120] No whitelist given. > Advertising offers for all slaves > I1028 02:38:31.522539 11903 slave.cpp:2997] Cleaning up executor 'default' > of framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:31.522729 11904 gc.cpp:56] Scheduling > '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7' > for gc 6.99999395104296days in the future > I1028 02:38:31.522784 11903 slave.cpp:3074] Cleaning up framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:31.522855 11899 status_update_manager.cpp:279] Closing status > update streams for framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:31.522948 11904 gc.cpp:56] Scheduling > '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default' > for gc 6.99999394972148days in the future > I1028 02:38:31.522985 11900 master.cpp:3462] Executor default of framework > 20141028-023804-3142697795-39931-11875-0000 on slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) exited with status 0 > I1028 02:38:31.523069 11904 gc.cpp:56] Scheduling > '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000' > for gc 6.99999394800889days in the future > I1028 02:38:31.523079 11900 master.cpp:4705] Removing executor 'default' > with resources cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25] of framework > 20141028-023804-3142697795-39931-11875-0000 on slave > 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 > (pomona.apache.org) > I1028 02:38:31.523833 11901 hierarchical_allocator_process.hpp:563] > Recovered cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25] (total > allocatable: cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25]) on slave > 20141028-023804-3142697795-39931-11875-S0 from framework > 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:31.524312 11901 hierarchical_allocator_process.hpp:563] > Recovered cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, > 20-22, 26-30] (total allocatable: cpus(*):2; mem(*):1024; ports(*):[1-10, > 20-30]; disk(*):1024) on slave 20141028-023804-3142697795-39931-11875-S0 > from framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:31.524363 11901 hierarchical_allocator_process.hpp:599] > Framework 20141028-023804-3142697795-39931-11875-0000 filtered slave > 20141028-023804-3142697795-39931-11875-S0 for 5secs > tests/master_tests.cpp:743: Failure > Failed to wait 10secs for offers > I1028 02:38:32.363447 11896 master.cpp:768] Framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > disconnected > I1028 02:38:32.363498 11896 master.cpp:1731] Disconnecting framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:32.363535 11896 master.cpp:1747] Deactivating framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:32.363697 11896 master.cpp:790] Giving framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 0ns to > failover > I1028 02:38:32.363828 11899 hierarchical_allocator_process.hpp:405] > Deactivated framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:32.363980 11898 master.cpp:3665] Framework failover timeout, > removing framework 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > I1028 02:38:32.364006 11898 master.cpp:4201] Removing framework > 20141028-023804-3142697795-39931-11875-0000 (default) at > scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 > tests/master_tests.cpp:729: Failure > Actual function call count doesn't match EXPECT_CALL(sched, > resourceOffers(&driver, _))... > Expected: to be called once > Actual: never called - unsatisfied and active > I1028 02:38:32.364336 11889 slave.cpp:1522] Asked to shut down framework > 20141028-023804-3142697795-39931-11875-0000 by master@67.195.81.187:39931 > W1028 02:38:32.364373 11889 slave.cpp:1537] Cannot shut down unknown > framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:32.364612 11898 hierarchical_allocator_process.hpp:360] > Removed framework 20141028-023804-3142697795-39931-11875-0000 > I1028 02:38:32.364822 11875 master.cpp:677] Master terminating > I1028 02:38:32.365265 11899 slave.cpp:2607] master@67.195.81.187:39931 > exited > W1028 02:38:32.365299 11899 slave.cpp:2610] Master disconnected! Waiting > for a new master to be elected > *** Aborted at 1414463912 (unix time) try "date -d @1414463912" if you are > using GNU date *** > PC: @ 0x1c52008 (unknown) > *** SIGSEGV (@0x1c52008) received by PID 11875 (TID 0x2ad3bf0f6100) from > PID 29696008; stack trace: *** > @ 0x2ad3c917685a call_chained_handler() > @ 0x2ad3c9173deb os::Linux::chained_handler() > @ 0x2ad3c9177420 JVM_handle_linux_signal > @ 0x2ad3c9173cfe signalHandler() > @ 0x2ad3c43be340 (unknown) > @ 0x1c52008 (unknown) > make[3]: *** [check-local] Segmentation fault > make[3]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src > '> > make[2]: *** [check-am] Error 2 > make[2]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src > '> > make[1]: *** [check] Error 2 > make[1]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src > '> > make: *** [check-recursive] Error 1 > Test finished > Exit status: 2 > Process leaked file descriptors. See > http://wiki.jenkins-ci.org/display/JENKINS/Spawning+processes+from+build > for more information > Build step 'Execute shell' marked build as failure > Recording test results >
