You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/03/06 03:44:42 UTC
[jira] [Created] (MESOS-1061)
GarbageCollectorIntegrationTest.DiskUsage is flaky
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 : master@192.168.122.134: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 master@192.168.122.134: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 master@192.168.122.134: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 master@192.168.122.134: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 master@192.168.122.134: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 master@192.168.122.134:33036
I0305 16:32:59.983324 27261 sched.cpp:267] Authenticating with master master@192.168.122.134: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 master@192.168.122.134:33036
I0305 16:32:59.984691 27261 sched.cpp:460] Sending registration request to master@192.168.122.134: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 master@192.168.122.134: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 master@192.168.122.134: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)