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
