See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2326/changes>
Changes: [benjamin.mahler] Refactored task launching in the master. ------------------------------------------ [...truncated 14902 lines...] I1203 00:23:36.451808 12663 replica.cpp:474] Replica received implicit promise request with proposal 1 I1203 00:23:36.452234 12663 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 397220ns I1203 00:23:36.452261 12663 replica.cpp:342] Persisted promised to 1 I1203 00:23:36.452739 12670 coordinator.cpp:230] Coordinator attemping to fill missing position I1203 00:23:36.453881 12656 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I1203 00:23:36.454227 12656 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 311180ns I1203 00:23:36.454252 12656 replica.cpp:676] Persisted action at 0 I1203 00:23:36.455245 12664 replica.cpp:508] Replica received write request for position 0 I1203 00:23:36.455307 12664 leveldb.cpp:438] Reading position from leveldb took 37417ns I1203 00:23:36.455641 12664 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 300283ns I1203 00:23:36.455662 12664 replica.cpp:676] Persisted action at 0 I1203 00:23:36.456176 12662 replica.cpp:655] Replica received learned notice for position 0 I1203 00:23:36.456342 12662 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 138095ns I1203 00:23:36.456377 12662 replica.cpp:676] Persisted action at 0 I1203 00:23:36.456406 12662 replica.cpp:661] Replica learned NOP action at position 0 I1203 00:23:36.456925 12658 log.cpp:672] Writer started with ending position 0 I1203 00:23:36.457842 12670 leveldb.cpp:438] Reading position from leveldb took 23234ns I1203 00:23:36.460652 12669 registrar.cpp:346] Successfully fetched the registry (0B) in 10.398976ms I1203 00:23:36.460743 12669 registrar.cpp:445] Applied 1 operations in 16567ns; attempting to update the 'registry' I1203 00:23:36.463471 12665 log.cpp:680] Attempting to append 139 bytes to the log I1203 00:23:36.463579 12663 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1203 00:23:36.464268 12667 replica.cpp:508] Replica received write request for position 1 I1203 00:23:36.464670 12667 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 348109ns I1203 00:23:36.464696 12667 replica.cpp:676] Persisted action at 1 I1203 00:23:36.465320 12656 replica.cpp:655] Replica received learned notice for position 1 I1203 00:23:36.465684 12656 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 333332ns I1203 00:23:36.465709 12656 replica.cpp:676] Persisted action at 1 I1203 00:23:36.465730 12656 replica.cpp:661] Replica learned APPEND action at position 1 I1203 00:23:36.466524 12659 registrar.cpp:490] Successfully updated the 'registry' in 5.730816ms I1203 00:23:36.466671 12659 registrar.cpp:376] Successfully recovered registrar I1203 00:23:36.467026 12658 log.cpp:699] Attempting to truncate the log to 1 I1203 00:23:36.467159 12662 master.cpp:1068] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register I1203 00:23:36.467185 12664 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1203 00:23:36.468052 12659 replica.cpp:508] Replica received write request for position 2 I1203 00:23:36.468487 12659 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 401600ns I1203 00:23:36.468511 12659 replica.cpp:676] Persisted action at 2 I1203 00:23:36.469133 12663 replica.cpp:655] Replica received learned notice for position 2 I1203 00:23:36.469548 12663 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 387178ns I1203 00:23:36.469594 12663 leveldb.cpp:401] Deleting ~1 keys from leveldb took 21092ns I1203 00:23:36.469611 12663 replica.cpp:676] Persisted action at 2 I1203 00:23:36.469632 12663 replica.cpp:661] Replica learned TRUNCATE action at position 2 I1203 00:23:36.486594 12656 slave.cpp:170] Slave started on 29)@67.195.81.187:35409 I1203 00:23:36.486634 12656 credentials.hpp:84] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_8OPeoT/credential' I1203 00:23:36.486783 12656 slave.cpp:279] Slave using credential for: test-principal I1203 00:23:36.486982 12656 slave.cpp:292] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1203 00:23:36.487078 12656 slave.cpp:321] Slave hostname: pomona.apache.org I1203 00:23:36.487095 12656 slave.cpp:322] Slave checkpoint: false W1203 00:23:36.487105 12656 slave.cpp:324] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag I1203 00:23:36.487690 12671 state.cpp:33] Recovering state from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_8OPeoT/meta' I1203 00:23:36.487905 12661 status_update_manager.cpp:197] Recovering status update manager I1203 00:23:36.488147 12666 slave.cpp:3482] Finished recovery I1203 00:23:36.488562 12656 status_update_manager.cpp:171] Pausing sending status updates I1203 00:23:36.488569 12658 slave.cpp:605] New master detected at [email protected]:35409 I1203 00:23:36.488633 12658 slave.cpp:668] Authenticating with master [email protected]:35409 I1203 00:23:36.488653 12658 slave.cpp:673] Using default CRAM-MD5 authenticatee I1203 00:23:36.488780 12658 slave.cpp:641] Detecting new master I1203 00:23:36.488848 12667 authenticatee.hpp:138] Creating new client SASL connection I1203 00:23:36.489033 12663 master.cpp:3821] Authenticating slave(29)@67.195.81.187:35409 I1203 00:23:36.489059 12663 master.cpp:3832] Using default CRAM-MD5 authenticator I1203 00:23:36.489296 12668 authenticator.hpp:170] Creating new server SASL connection I1203 00:23:36.489472 12664 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I1203 00:23:36.489506 12664 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I1203 00:23:36.489590 12662 authenticator.hpp:276] Received SASL authentication start I1203 00:23:36.489631 12662 authenticator.hpp:398] Authentication requires more steps I1203 00:23:36.489708 12667 authenticatee.hpp:275] Received SASL authentication step I1203 00:23:36.489806 12662 authenticator.hpp:304] Received SASL authentication step I1203 00:23:36.489838 12662 auxprop.cpp:99] 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 I1203 00:23:36.489856 12662 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I1203 00:23:36.489893 12662 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1203 00:23:36.489933 12662 auxprop.cpp:99] 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 I1203 00:23:36.489948 12662 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1203 00:23:36.489955 12662 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1203 00:23:36.489971 12662 authenticator.hpp:390] Authentication success I1203 00:23:36.490046 12660 authenticatee.hpp:315] Authentication success I1203 00:23:36.490062 12658 master.cpp:3879] Successfully authenticated principal 'test-principal' at slave(29)@67.195.81.187:35409 I1203 00:23:36.490309 12671 slave.cpp:739] Successfully authenticated with master [email protected]:35409 I1203 00:23:36.491097 12671 slave.cpp:1067] Will retry registration in 11.753605ms if necessary I1203 00:23:36.491437 12662 master.cpp:2979] Registering slave at slave(29)@67.195.81.187:35409 (pomona.apache.org) with id 20141203-002336-3142697795-35409-12642-S0 I1203 00:23:36.491888 12665 registrar.cpp:445] Applied 1 operations in 81544ns; attempting to update the 'registry' I1203 00:23:36.493561 12642 sched.cpp:148] Version: 0.22.0 I1203 00:23:36.494112 12664 sched.cpp:245] New master detected at [email protected]:35409 I1203 00:23:36.494169 12664 sched.cpp:301] Authenticating with master [email protected]:35409 I1203 00:23:36.494205 12664 sched.cpp:308] Using default CRAM-MD5 authenticatee I1203 00:23:36.494503 12661 authenticatee.hpp:138] Creating new client SASL connection I1203 00:23:36.494659 12669 log.cpp:680] Attempting to append 316 bytes to the log I1203 00:23:36.494791 12657 master.cpp:3821] Authenticating [email protected]:35409 I1203 00:23:36.494799 12666 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1203 00:23:36.494828 12657 master.cpp:3832] Using default CRAM-MD5 authenticator I1203 00:23:36.495090 12660 authenticator.hpp:170] Creating new server SASL connection I1203 00:23:36.495224 12657 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I1203 00:23:36.495252 12657 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I1203 00:23:36.495352 12661 authenticator.hpp:276] Received SASL authentication start I1203 00:23:36.495404 12661 authenticator.hpp:398] Authentication requires more steps I1203 00:23:36.495560 12657 replica.cpp:508] Replica received write request for position 3 I1203 00:23:36.495565 12663 authenticatee.hpp:275] Received SASL authentication step I1203 00:23:36.495692 12663 authenticator.hpp:304] Received SASL authentication step I1203 00:23:36.495744 12663 auxprop.cpp:99] 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 I1203 00:23:36.495759 12663 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I1203 00:23:36.495757 12657 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 169349ns I1203 00:23:36.495780 12657 replica.cpp:676] Persisted action at 3 I1203 00:23:36.495790 12663 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1203 00:23:36.495823 12663 auxprop.cpp:99] 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 I1203 00:23:36.495839 12663 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1203 00:23:36.495852 12663 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1203 00:23:36.495868 12663 authenticator.hpp:390] Authentication success I1203 00:23:36.495949 12666 authenticatee.hpp:315] Authentication success I1203 00:23:36.495985 12661 master.cpp:3879] Successfully authenticated principal 'test-principal' at [email protected]:35409 I1203 00:23:36.496253 12663 sched.cpp:389] Successfully authenticated with master [email protected]:35409 I1203 00:23:36.496301 12663 sched.cpp:512] Sending registration request to [email protected]:35409 I1203 00:23:36.496381 12663 sched.cpp:545] Will retry registration in 1.64670895secs if necessary I1203 00:23:36.496445 12657 master.cpp:1330] Received registration request for framework 'default' at [email protected]:35409 I1203 00:23:36.496453 12664 replica.cpp:655] Replica received learned notice for position 3 I1203 00:23:36.496505 12657 master.cpp:1289] Authorizing framework principal 'test-principal' to receive offers for role '*' I1203 00:23:36.496848 12664 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 366628ns I1203 00:23:36.496868 12664 replica.cpp:676] Persisted action at 3 I1203 00:23:36.496884 12664 replica.cpp:661] Replica learned APPEND action at position 3 I1203 00:23:36.496937 12660 master.cpp:1394] Registering framework 20141203-002336-3142697795-35409-12642-0000 (default) at [email protected]:35409 I1203 00:23:36.497366 12661 hierarchical_allocator_process.hpp:329] Added framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.497397 12661 hierarchical_allocator_process.hpp:703] No resources available to allocate! I1203 00:23:36.497416 12661 hierarchical_allocator_process.hpp:665] Performed allocation for 0 slaves in 21940ns I1203 00:23:36.497805 12662 sched.cpp:439] Framework registered with 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.497858 12662 sched.cpp:453] Scheduler::registered took 26667ns I1203 00:23:36.498123 12667 registrar.cpp:490] Successfully updated the 'registry' in 6.170112ms I1203 00:23:36.498389 12658 log.cpp:699] Attempting to truncate the log to 3 I1203 00:23:36.498497 12661 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1203 00:23:36.498730 12669 master.cpp:3033] Registered slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1203 00:23:36.498805 12656 slave.cpp:2553] Received ping from slave-observer(31)@67.195.81.187:35409 I1203 00:23:36.499004 12656 slave.cpp:773] Registered with master [email protected]:35409; given slave ID 20141203-002336-3142697795-35409-12642-S0 I1203 00:23:36.498949 12664 hierarchical_allocator_process.hpp:442] Added slave 20141203-002336-3142697795-35409-12642-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) I1203 00:23:36.499119 12663 status_update_manager.cpp:178] Resuming sending status updates I1203 00:23:36.499214 12664 hierarchical_allocator_process.hpp:740] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141203-002336-3142697795-35409-12642-S0 to framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.499361 12661 replica.cpp:508] Replica received write request for position 4 I1203 00:23:36.499552 12664 hierarchical_allocator_process.hpp:685] Performed allocation for slave 20141203-002336-3142697795-35409-12642-S0 in 486107ns I1203 00:23:36.499855 12661 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 461141ns I1203 00:23:36.499886 12661 replica.cpp:676] Persisted action at 4 I1203 00:23:36.499883 12669 master.cpp:3763] Sending 1 offers to framework 20141203-002336-3142697795-35409-12642-0000 (default) at [email protected]:35409 I1203 00:23:36.500550 12660 replica.cpp:655] Replica received learned notice for position 4 I1203 00:23:36.500941 12660 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 363071ns I1203 00:23:36.500957 12671 sched.cpp:602] Scheduler::resourceOffers took 694378ns I1203 00:23:36.500991 12660 leveldb.cpp:401] Deleting ~2 keys from leveldb took 26817ns I1203 00:23:36.501010 12660 replica.cpp:676] Persisted action at 4 I1203 00:23:36.501032 12660 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1203 00:23:36.501744 12665 master.cpp:2310] Processing reply for offers: [ 20141203-002336-3142697795-35409-12642-O0 ] on slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) for framework 20141203-002336-3142697795-35409-12642-0000 (default) at [email protected]:35409 I1203 00:23:36.501780 12665 master.cpp:2408] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' W1203 00:23:36.502473 12664 master.cpp:1945] 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. W1203 00:23:36.502512 12664 master.cpp:1957] 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. I1203 00:23:36.502778 12664 master.hpp:759] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20141203-002336-3142697795-35409-12642-S0 (pomona.apache.org) I1203 00:23:36.502862 12664 master.cpp:2607] Launching task 0 of framework 20141203-002336-3142697795-35409-12642-0000 (default) at [email protected]:35409 with resources cpus(*):1; mem(*):512 on slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) I1203 00:23:36.503170 12671 slave.cpp:1098] Got assigned task 0 for framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.503376 12663 hierarchical_allocator_process.hpp:569] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]) on slave 20141203-002336-3142697795-35409-12642-S0 from framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.503427 12663 hierarchical_allocator_process.hpp:605] Framework 20141203-002336-3142697795-35409-12642-0000 filtered slave 20141203-002336-3142697795-35409-12642-S0 for 5secs I1203 00:23:36.503736 12671 slave.cpp:1208] Launching task 0 for framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.506360 12671 slave.cpp:3864] Launching executor default of framework 20141203-002336-3142697795-35409-12642-0000 in work directory '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_8OPeoT/slaves/20141203-002336-3142697795-35409-12642-S0/frameworks/20141203-002336-3142697795-35409-12642-0000/executors/default/runs/b23a64f3-1700-47a1-ac04-f3dcae883d37' I1203 00:23:36.509353 12671 exec.cpp:132] Version: 0.22.0 I1203 00:23:36.509630 12665 exec.cpp:182] Executor started at: executor(18)@67.195.81.187:35409 with pid 12642 I1203 00:23:36.509742 12671 slave.cpp:1331] Queuing task '0' for executor default of framework '20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.509862 12671 slave.cpp:558] Successfully attached file '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_8OPeoT/slaves/20141203-002336-3142697795-35409-12642-S0/frameworks/20141203-002336-3142697795-35409-12642-0000/executors/default/runs/b23a64f3-1700-47a1-ac04-f3dcae883d37' I1203 00:23:36.509980 12671 slave.cpp:2855] Monitoring executor 'default' of framework '20141203-002336-3142697795-35409-12642-0000' in container 'b23a64f3-1700-47a1-ac04-f3dcae883d37' I1203 00:23:36.510154 12671 slave.cpp:1875] Got registration for executor 'default' of framework 20141203-002336-3142697795-35409-12642-0000 from executor(18)@67.195.81.187:35409 I1203 00:23:36.510524 12671 slave.cpp:1994] Flushing queued task 0 for executor 'default' of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.510638 12662 exec.cpp:206] Executor registered on slave 20141203-002336-3142697795-35409-12642-S0 I1203 00:23:36.512820 12662 exec.cpp:218] Executor::registered took 28252ns I1203 00:23:36.512986 12662 exec.cpp:293] Executor asked to run task '0' I1203 00:23:36.513075 12662 exec.cpp:302] Executor::launchTask took 67101ns I1203 00:23:36.515220 12662 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.515486 12662 slave.cpp:2230] Handling status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 from executor(18)@67.195.81.187:35409 I1203 00:23:36.515733 12657 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.515777 12657 status_update_manager.cpp:494] Creating StatusUpdate stream for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.516005 12657 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to the slave I1203 00:23:36.516227 12661 slave.cpp:2473] Forwarding the update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to [email protected]:35409 I1203 00:23:36.516388 12661 slave.cpp:2400] Status update manager successfully handled status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.516420 12661 slave.cpp:2406] Sending acknowledgement for status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to executor(18)@67.195.81.187:35409 I1203 00:23:36.516589 12666 exec.cpp:339] Executor received status update acknowledgement 09296186-d21b-44c1-b47d-60038f0aa2f9 for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.516589 12668 master.cpp:3356] Forwarding status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.516746 12668 master.cpp:3328] Status update TASK_RUNNING (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 from slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) I1203 00:23:36.516794 12668 master.cpp:4613] Updating the latest state of task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to TASK_RUNNING I1203 00:23:36.516952 12661 sched.cpp:693] Scheduler::statusUpdate took 65611ns I1203 00:23:36.517335 12665 master.cpp:2829] Forwarding status update acknowledgement 09296186-d21b-44c1-b47d-60038f0aa2f9 for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 (default) at [email protected]:35409 to slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) I1203 00:23:36.517845 12668 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.518033 12668 slave.cpp:1815] Status update manager successfully handled status update acknowledgement (UUID: 09296186-d21b-44c1-b47d-60038f0aa2f9) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.520233 12657 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.520463 12657 slave.cpp:2230] Handling status update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 from executor(18)@67.195.81.187:35409 I1203 00:23:36.520570 12657 slave.cpp:4172] Terminating task 0 I1203 00:23:36.520999 12669 status_update_manager.cpp:317] Received status update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.521090 12669 status_update_manager.cpp:371] Forwarding update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to the slave I1203 00:23:36.521273 12656 slave.cpp:2473] Forwarding the update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to [email protected]:35409 I1203 00:23:36.521477 12656 slave.cpp:2400] Status update manager successfully handled status update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.521507 12656 slave.cpp:2406] Sending acknowledgement for status update TASK_FINISHED (UUID: d2b397a8-cbcc-412b-9e6b-276014b6639c) for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 to executor(18)@67.195.81.187:35409 I1203 00:23:36.521832 12656 exec.cpp:339] Executor received status update acknowledgement d2b397a8-cbcc-412b-9e6b-276014b6639c for task 0 of framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:36.522259 12660 slave.cpp:2913] Executor 'default' of framework 20141203-002336-3142697795-35409-12642-0000 exited with status 0 Itests/master_slave_reconciliation_tests.cpp:150: Failure Failed to wait 10secs for status2 1203 00:23:36.522747 12665 master.cpp:3408] Executor default of framework 20141203-002336-3142697795-35409-12642-0000 on slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) exited with status 0 tests/master_slave_reconciliation_tests.cpp:140: Failure Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))... Expected: to be called once Actual: never called - unsatisfied and active I1203 00:23:36.524992 12668 status_update_manager.cpp:171] Pausing sending status updates I1203 00:23:36.524997 12669 slave.cpp:605] New master detected at [email protected]:35409 I1203 00:23:37.450222 12662 hierarchical_allocator_process.hpp:822] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20141203-002336-3142697795-35409-12642-S0 for framework 20141203-002336-3142697795-35409-12642-0000 I1203 00:23:54.853981 12662 hierarchical_allocator_process.hpp:665] Performed allocation for 1 slaves in 17.40404246secs I1203 00:23:54.854054 12665 master.cpp:4701] Removing executor 'default' with resources of framework 20141203-002336-3142697795-35409-12642-0000 on slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) I1203 00:23:54.854231 12669 slave.cpp:668] Authenticating with master [email protected]:35409 I1203 00:23:54.854267 12669 slave.cpp:673] Using default CRAM-MD5 authenticatee I1203 00:23:54.855202 12669 slave.cpp:641] Detecting new master F1203 00:23:54.855202 12669 logging.cpp:57] RAW: Pure virtual method called I1203 00:23:54.855481 12658 authenticatee.hpp:138] Creating new client SASL connection I1203 00:23:54.855736 12665 master.cpp:645] Master terminating W1203 00:23:54.855972 12665 master.cpp:4658] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20141203-002336-3142697795-35409-12642-0000 on slave 20141203-002336-3142697795-35409-12642-S0 at slave(29)@67.195.81.187:35409 (pomona.apache.org) in non-terminal state TASK_RUNNING I1203 00:23:54.856400 12656 hierarchical_allocator_process.hpp:569] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141203-002336-3142697795-35409-12642-S0 from framework 20141203-002336-3142697795-35409-12642-0000 @ 0x2b0125b5e5cc google::LogMessage::Fail() @ 0x2b0125b63cc0 google::RawLog__() @ 0x2b01252412fa __cxa_pure_virtual @ 0x2b01254d1f0a mesos::internal::slave::Slave::detected() @ 0x2b012550cfb5 _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureI6OptionINS1_10MasterInfoEEEES9_EEvRKNS_3PIDIT_EEMSD_FvT0_ET1_ENKUlPNS_11ProcessBaseEE_clESM_ F1203 00:23:54.856400 12642 logging.cpp:57] RAW: Pure virtual method called @ 0x2b0125b5e5cc google::LogMessage::Fail() @ 0x2b0125b63cc0 google::RawLog__() @ 0x2b0125533532 _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureI6OptionINS5_10MasterInfoEEEESD_EEvRKNS0_3PIDIT_EEMSH_FvT0_ET1_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_ @ 0x2b01252412fa __cxa_pure_virtual @ 0x8e074b mesos::internal::tests::Cluster::Slaves::shutdown() @ 0xdda050 mesos::internal::tests::MesosTest::ShutdownSlaves() @ 0x2b0125af1a8d std::function<>::operator()() @ 0xdda014 mesos::internal::tests::MesosTest::Shutdown() @ 0x2b0125ad8cbf process::ProcessBase::visit() @ 0xdd781b mesos::internal::tests::MesosTest::TearDown() @ 0x2b0125add4ea process::DispatchEvent::visit() @ 0x1096704 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x8d26a2 process::ProcessBase::serve() @ 0x109185a testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x1079bb4 testing::Test::Run() @ 0x2b0125ad5758 process::ProcessManager::resume() @ 0x107a28e testing::TestInfo::Run() @ 0x107a816 testing::TestCase::Run() @ 0x2b0125ac9cdb process::schedule() @ 0x2b0127e1b182 start_thread @ 0x2b012812bfbd (unknown) make[3]: *** [check-local] Aborted 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
