Vinod Kone created MESOS-1061:
---------------------------------
Summary: GarbageCollectorIntegrationTest.DiskUsage is flaky
Key: MESOS-1061
URL: https://issues.apache.org/jira/browse/MESOS-1061
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Vinod Kone
Fix For: 0.19.0
[ RUN ] GarbageCollectorIntegrationTest.DiskUsage
I0305 16:32:59.974095 27236 master.cpp:252] Master ID:
2014-03-05-16:32:59-2256185536-33036-27236 Hostname: fedora-19
I0305 16:32:59.974203 27260 master.cpp:262] Master started on
192.168.122.134:33036
I0305 16:32:59.974215 27260 master.cpp:265] Master only allowing authenticated
frameworks to register!
I0305 16:32:59.974628 27260 hierarchical_allocator_process.hpp:302]
Initializing hierarchical allocator process with master :
[email protected]:33036
I0305 16:32:59.974663 27260 master.cpp:96] No whitelist given. Advertising
offers for all slaves
I0305 16:32:59.974808 27260 master.cpp:771] The newly elected leader is
[email protected]:33036 with id 2014-03-05-16:32:59-2256185536-33036-27236
I0305 16:32:59.974820 27260 master.cpp:781] Elected as the leading master!
I0305 16:32:59.977638 27259 slave.cpp:119] Slave started on
53)@192.168.122.134:33036
I0305 16:32:59.977720 27259 slave.cpp:129] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0305 16:32:59.978029 27259 slave.cpp:157] Slave hostname: fedora-19
I0305 16:32:59.978042 27259 slave.cpp:158] Slave checkpoint: false
I0305 16:32:59.978410 27259 state.cpp:33] Recovering state from
'/tmp/GarbageCollectorIntegrationTest_DiskUsage_vsBzsr/meta'
I0305 16:32:59.978499 27259 status_update_manager.cpp:193] Recovering status
update manager
I0305 16:32:59.978569 27259 slave.cpp:2710] Finished recovery
I0305 16:32:59.978806 27259 slave.cpp:404] New master detected at
[email protected]:33036
I0305 16:32:59.978853 27259 slave.cpp:429] Detecting new master
I0305 16:32:59.978884 27259 status_update_manager.cpp:167] New master detected
at [email protected]:33036
I0305 16:32:59.978936 27259 master.cpp:1858] Attempting to register slave on
fedora-19 at slave(53)@192.168.122.134:33036
I0305 16:32:59.978947 27259 master.cpp:2842] Adding slave
2014-03-05-16:32:59-2256185536-33036-27236-0 at fedora-19 with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0305 16:32:59.979054 27259 slave.cpp:447] Registered with master
[email protected]:33036; given slave ID
2014-03-05-16:32:59-2256185536-33036-27236-0
I0305 16:32:59.979115 27259 hierarchical_allocator_process.hpp:445] Added slave
2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] available)
I0305 16:32:59.979151 27259 hierarchical_allocator_process.hpp:708] Performed
allocation for slave 2014-03-05-16:32:59-2256185536-33036-27236-0 in 7240ns
I0305 16:32:59.982027 27236 sched.cpp:121] Version: 0.19.0
I0305 16:32:59.983299 27261 sched.cpp:217] New master detected at
[email protected]:33036
I0305 16:32:59.983324 27261 sched.cpp:267] Authenticating with master
[email protected]:33036
I0305 16:32:59.983407 27261 authenticatee.hpp:128] Creating new client SASL
connection
I0305 16:32:59.983818 27261 master.cpp:2355] Authenticating framework at
scheduler(70)@192.168.122.134:33036
I0305 16:32:59.983898 27261 authenticator.hpp:148] Creating new server SASL
connection
I0305 16:32:59.984202 27261 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0305 16:32:59.984222 27261 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0305 16:32:59.984396 27261 authenticator.hpp:254] Received SASL authentication
start
I0305 16:32:59.984438 27261 authenticator.hpp:342] Authentication requires more
steps
I0305 16:32:59.984472 27261 authenticatee.hpp:265] Received SASL authentication
step
I0305 16:32:59.984508 27261 authenticator.hpp:282] Received SASL authentication
step
I0305 16:32:59.984524 27261 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0305 16:32:59.984531 27261 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0305 16:32:59.984544 27261 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0305 16:32:59.984552 27261 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0305 16:32:59.984558 27261 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0305 16:32:59.984563 27261 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0305 16:32:59.984575 27261 authenticator.hpp:334] Authentication success
I0305 16:32:59.984598 27261 authenticatee.hpp:305] Authentication success
I0305 16:32:59.984618 27261 master.cpp:2395] Successfully authenticated
framework at scheduler(70)@192.168.122.134:33036
I0305 16:32:59.984678 27261 sched.cpp:341] Successfully authenticated with
master [email protected]:33036
I0305 16:32:59.984691 27261 sched.cpp:460] Sending registration request to
[email protected]:33036
I0305 16:32:59.984731 27261 master.cpp:829] Received registration request from
scheduler(70)@192.168.122.134:33036
I0305 16:32:59.984753 27261 master.cpp:847] Registering framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 at
scheduler(70)@192.168.122.134:33036
I0305 16:32:59.984802 27261 sched.cpp:391] Framework registered with
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.984823 27261 sched.cpp:405] Scheduler::registered took 9942ns
I0305 16:32:59.984850 27261 hierarchical_allocator_process.hpp:332] Added
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.984885 27261 hierarchical_allocator_process.hpp:752] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 to framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.984977 27261 hierarchical_allocator_process.hpp:688] Performed
allocation for 1 slaves in 114500ns
I0305 16:32:59.985024 27261 master.hpp:456] Adding offer
2014-03-05-16:32:59-2256185536-33036-27236-0 with resources cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19)
I0305 16:32:59.985061 27261 master.cpp:2310] Sending 1 offers to framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.986477 27261 sched.cpp:528] Scheduler::resourceOffers took
1.343035ms
I0305 16:32:59.987185 27260 master.hpp:466] Removing offer
2014-03-05-16:32:59-2256185536-33036-27236-0 with resources cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19)
I0305 16:32:59.987264 27260 master.cpp:1585] Processing reply for offers: [
2014-03-05-16:32:59-2256185536-33036-27236-0 ] on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19) for framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.987331 27260 master.hpp:428] Adding task 0 with resources
cpus(*):2; mem(*):1024 on slave 2014-03-05-16:32:59-2256185536-33036-27236-0
(fedora-19)
I0305 16:32:59.987438 27260 master.cpp:2479] Launching task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 with resources cpus(*):2;
mem(*):1024 on slave 2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19)
I0305 16:32:59.987557 27260 slave.cpp:665] Got assigned task 0 for framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.987720 27260 slave.cpp:774] Launching task 0 for framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.988298 27262 hierarchical_allocator_process.hpp:547] Framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 left disk(*):1024;
ports(*):[31000-32000] unused on slave
2014-03-05-16:32:59-2256185536-33036-27236-0
I0305 16:32:59.988351 27262 hierarchical_allocator_process.hpp:590] Framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 filtered slave
2014-03-05-16:32:59-2256185536-33036-27236-0 for 5secs
I0305 16:32:59.990694 27260 exec.cpp:131] Version: 0.19.0
I0305 16:32:59.991338 27257 exec.cpp:181] Executor started at:
executor(24)@192.168.122.134:33036 with pid 27236
I0305 16:32:59.991952 27260 slave.cpp:884] Queuing task '0' for executor
default of framework '2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.991998 27260 slave.cpp:365] Successfully attached file
'/tmp/GarbageCollectorIntegrationTest_DiskUsage_vsBzsr/slaves/2014-03-05-16:32:59-2256185536-33036-27236-0/frameworks/2014-03-05-16:32:59-2256185536-33036-27236-0000/executors/default/runs/310ad836-472b-4aa2-a8e4-df68e2a9c66b'
I0305 16:32:59.992024 27260 slave.cpp:1356] Got registration for executor
'default' of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.992682 27259 exec.cpp:205] Executor registered on slave
2014-03-05-16:32:59-2256185536-33036-27236-0
I0305 16:32:59.993489 27259 exec.cpp:217] Executor::registered took 15912ns
I0305 16:32:59.994130 27260 slave.cpp:1474] Flushing queued task 0 for executor
'default' of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.994763 27255 exec.cpp:292] Executor asked to run task '0'
I0305 16:32:59.994803 27255 exec.cpp:301] Executor::launchTask took 22823ns
I0305 16:32:59.995609 27255 exec.cpp:524] Executor sending status update
TASK_RUNNING (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.996297 27260 slave.cpp:2029] Monitoring executor 'default' of
framework '2014-03-05-16:32:59-2256185536-33036-27236-0000' in container
'310ad836-472b-4aa2-a8e4-df68e2a9c66b'
I0305 16:32:59.996945 27260 slave.cpp:1683] Handling status update TASK_RUNNING
(UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 from
executor(24)@192.168.122.134:33036
I0305 16:32:59.997689 27261 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.997710 27261 status_update_manager.cpp:499] Creating
StatusUpdate stream for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.997761 27261 status_update_manager.cpp:373] Forwarding status
update TASK_RUNNING (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000 to
[email protected]:33036
I0305 16:32:59.997871 27257 master.cpp:2042] Status update TASK_RUNNING (UUID:
3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 from
slave(53)@192.168.122.134:33036
I0305 16:32:59.997931 27257 sched.cpp:619] Scheduler::statusUpdate took 14057ns
I0305 16:32:59.998798 27259 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0
of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.999398 27260 slave.cpp:1803] Status update manager successfully
handled status update TASK_RUNNING (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb)
for task 0 of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:32:59.999418 27260 slave.cpp:1809] Sending acknowledgement for status
update TASK_RUNNING (UUID: 3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000 to
executor(24)@192.168.122.134:33036
I0305 16:33:00.013356 27260 slave.cpp:1296] Status update manager successfully
handled status update acknowledgement (UUID:
3aec2071-bd99-4dcb-87f1-2918782b46cb) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.014122 27256 slave.cpp:2087] Executor 'default' of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 has exited with status 0
I0305 16:33:00.018606 27256 slave.cpp:1683] Handling status update TASK_LOST
(UUID: bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 from @0.0.0.0:0
I0305 16:33:00.018647 27256 slave.cpp:3182] Terminating task 0
I0305 16:33:00.018777 27256 status_update_manager.cpp:320] Received status
update TASK_LOST (UUID: bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.018807 27256 status_update_manager.cpp:373] Forwarding status
update TASK_LOST (UUID: bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0 of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000 to
[email protected]:33036
I0305 16:33:00.018910 27256 master.cpp:2115] Executor default of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 (fedora-19) has exited with status 0
I0305 16:33:00.019011 27256 master.cpp:2042] Status update TASK_LOST (UUID:
bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000 from
slave(53)@192.168.122.134:33036
I0305 16:33:00.019053 27256 master.hpp:446] Removing task 0 with resources
cpus(*):2; mem(*):1024 on slave 2014-03-05-16:32:59-2256185536-33036-27236-0
(fedora-19)
I0305 16:33:00.019121 27256 slave.cpp:1803] Status update manager successfully
handled status update TASK_LOST (UUID: bd0266ab-150a-4c96-838a-c893cf82c25b)
for task 0 of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.019186 27256 hierarchical_allocator_process.hpp:637] Recovered
cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024;
ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave
2014-03-05-16:32:59-2256185536-33036-27236-0 from framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.020098 27256 sched.cpp:619] Scheduler::statusUpdate took 13958ns
I0305 16:33:00.020797 27262 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0
of framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.020828 27262 status_update_manager.cpp:530] Cleaning up status
update stream for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.020901 27262 slave.cpp:1296] Status update manager successfully
handled status update acknowledgement (UUID:
bd0266ab-150a-4c96-838a-c893cf82c25b) for task 0 of framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.020917 27262 slave.cpp:3205] Completing task 0
I0305 16:33:00.020926 27262 slave.cpp:2226] Cleaning up executor 'default' of
framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.021029 27262 slave.cpp:2301] Cleaning up framework
2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.021087 27262 gc.cpp:56] Scheduling
'/tmp/GarbageCollectorIntegrationTest_DiskUsage_vsBzsr/slaves/2014-03-05-16:32:59-2256185536-33036-27236-0/frameworks/2014-03-05-16:32:59-2256185536-33036-27236-0000/executors/default/runs/310ad836-472b-4aa2-a8e4-df68e2a9c66b'
for gc 1.00000000228825weeks in the future
I0305 16:33:00.021131 27262 gc.cpp:56] Scheduling
'/tmp/GarbageCollectorIntegrationTest_DiskUsage_vsBzsr/slaves/2014-03-05-16:32:59-2256185536-33036-27236-0/frameworks/2014-03-05-16:32:59-2256185536-33036-27236-0000/executors/default'
for gc 1.00000000228825weeks in the future
I0305 16:33:00.021159 27262 gc.cpp:56] Scheduling
'/tmp/GarbageCollectorIntegrationTest_DiskUsage_vsBzsr/slaves/2014-03-05-16:32:59-2256185536-33036-27236-0/frameworks/2014-03-05-16:32:59-2256185536-33036-27236-0000'
for gc 1.00000000228825weeks in the future
I0305 16:33:00.021185 27262 status_update_manager.cpp:282] Closing status
update streams for framework 2014-03-05-16:32:59-2256185536-33036-27236-0000
I0305 16:33:00.040454 27255 slave.cpp:2551] Current usage 90.00%. Max allowed
age: 0ns
tests/gc_tests.cpp:657: Failure
Value of: os::exists(executorDir)
Actual: true
Expected: false
Build timed out (after 180 minutes). Marking the build as failed.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
