[
https://issues.apache.org/jira/browse/MESOS-410?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13701659#comment-13701659
]
Benjamin Mahler edited comment on MESOS-410 at 7/8/13 5:24 AM:
---------------------------------------------------------------
Looks like this is still flaky on Jenkins:
https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1115/
[ RUN ] AllocatorTest/0.SchedulerFailover
I0706 13:49:32.603111 3700 master.cpp:230] Master started on 67.195.138.9:49663
I0706 13:49:32.713898 3700 master.cpp:245] Master ID:
201307061349-160088899-49663-3668
I0706 13:49:32.604032 3703 sched.cpp:177] New master at
[email protected]:49663
I0706 13:49:32.603664 3704 slave.cpp:113] Slave started on
92)@67.195.138.9:49663
W0706 13:49:32.825726 3699 master.cpp:83] No whitelist given. Advertising
offers for all slaves
I0706 13:49:32.825882 3705 hierarchical_allocator_process.hpp:305]
Initializing hierarchical allocator process with master :
[email protected]:49663
I0706 13:49:32.825920 3700 master.cpp:583] Elected as master!
I0706 13:49:33.040659 3704 slave.cpp:205] Slave resources: cpus=3; mem=1024;
ports=[31000-32000]; disk=775878
I0706 13:49:33.363317 3700 master.cpp:633] Registering framework
201307061349-160088899-49663-3668-0000 at scheduler(83)@67.195.138.9:49663
I0706 13:49:33.471230 3704 slave.cpp:529] New master detected at
[email protected]:49663
I0706 13:49:33.526826 3700 sched.cpp:222] Framework registered with
201307061349-160088899-49663-3668-0000
I0706 13:49:33.526926 3705 hierarchical_allocator_process.hpp:335] Added
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:33.534617 3704 slave.cpp:544] Postponing registration until
recovery is complete
I0706 13:49:33.534627 3703 status_update_manager.cpp:155] New master detected
at [email protected]:49663
I0706 13:49:33.650123 3705 hierarchical_allocator_process.hpp:704] No
resources available to allocate!
I0706 13:49:33.753705 3704 slave.cpp:390] Finished recovery
I0706 13:49:33.972802 3705 hierarchical_allocator_process.hpp:666] Performed
allocation for 0 slaves in 322.686119ms
I0706 13:49:34.080523 3699 master.cpp:962] Attempting to register slave on
vesta.apache.org at slave(92)@67.195.138.9:49663
I0706 13:49:34.199889 3699 master.cpp:1929] Adding slave
201307061349-160088899-49663-3668-0 at vesta.apache.org with cpus=3; mem=1024;
ports=[31000-32000]; disk=775878
I0706 13:49:34.260555 3706 hierarchical_allocator_process.hpp:704] No
resources available to allocate!
I0706 13:49:34.314430 3704 slave.cpp:589] Registered with master
[email protected]:49663; given slave ID 201307061349-160088899-49663-3668-0
I0706 13:49:34.433764 3706 hierarchical_allocator_process.hpp:666] Performed
allocation for 0 slaves in 173.257394ms
I0706 13:49:34.666087 3706 hierarchical_allocator_process.hpp:448] Added slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) with cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 (and cpus=3; mem=1024; ports=[31000-32000];
disk=775878 available)
I0706 13:49:34.780099 3706 hierarchical_allocator_process.hpp:726] Offering
cpus=3; mem=1024; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:34.903579 3706 hierarchical_allocator_process.hpp:686] Performed
allocation for slave 201307061349-160088899-49663-3668-0 in 123.5028ms
I0706 13:49:34.903635 3704 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-0 with resources cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.130395 3704 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.250018 3702 master.cpp:1543] Processing reply for offer
201307061349-160088899-49663-3668-0 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.359308 3702 master.hpp:305] Adding task 0 with resources
cpus=1; mem=256 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.476686 3702 master.cpp:1662] Launching task 0 of framework
201307061349-160088899-49663-3668-0000 with resources cpus=1; mem=256 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org)
I0706 13:49:35.588238 3702 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-0 with resources cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.588278 3704 slave.cpp:739] Got assigned task 0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.588335 3699 hierarchical_allocator_process.hpp:525] Framework
201307061349-160088899-49663-3668-0000 left cpus=2; mem=768;
ports=[31000-32000]; disk=775878 unused on slave
201307061349-160088899-49663-3668-0
I0706 13:49:35.811238 3704 slave.cpp:837] Launching task 0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.929050 3699 hierarchical_allocator_process.hpp:726] Offering
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:36.047159 3704 paths.hpp:303] Created executor directory
'/tmp/AllocatorTest_0_SchedulerFailover_HBQWdJ/slaves/201307061349-160088899-49663-3668-0/frameworks/201307061349-160088899-49663-3668-0000/executors/default/runs/76dcfb35-84c8-48d3-949c-df1887fa5b49'
I0706 13:49:36.161496 3699 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 232.455392ms
I0706 13:49:36.161623 3705 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-1 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:36.276984 3704 slave.cpp:948] Queuing task '0' for executor
default of framework '201307061349-160088899-49663-3668-0000
I0706 13:49:36.277175 3706 exec.cpp:170] Executor started at:
executor(31)@67.195.138.9:49663 with pid 3668
I0706 13:49:36.499796 3705 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:36.615203 3704 slave.cpp:511] Successfully attached file
'/tmp/AllocatorTest_0_SchedulerFailover_HBQWdJ/slaves/201307061349-160088899-49663-3668-0/frameworks/201307061349-160088899-49663-3668-0000/executors/default/runs/76dcfb35-84c8-48d3-949c-df1887fa5b49'
I0706 13:49:36.845386 3705 master.cpp:1543] Processing reply for offer
201307061349-160088899-49663-3668-1 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) for framework
201307061349-160088899-49663-3668-0000
tests/allocator_tests.cpp:674: Failure
Mock function called more times than expected - taking default action specified
at:
./tests/mesos.hpp:361:
Function call: resourcesUnused(@0x2b404401a478
201307061349-160088899-49663-3668-0000, @0x2b404401a458
201307061349-160088899-49663-3668-0, @0x2b404401a420 { cpus=2, mem=768,
ports=[31000-32000], disk=775878 }, @0x2b404401a410 16-byte object <00-00 00-00
40-2B 00-00 30-42 01-44 40-2B 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I0706 13:49:36.957567 3704 slave.cpp:1395] Got registration for executor
'default' of framework 201307061349-160088899-49663-3668-0000
I0706 13:49:37.065049 3705 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-1 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:37.065214 3701 hierarchical_allocator_process.hpp:525] Framework
201307061349-160088899-49663-3668-0000 left cpus=2; mem=768;
ports=[31000-32000]; disk=775878 unused on slave
201307061349-160088899-49663-3668-0
I0706 13:49:37.176506 3704 slave.cpp:1510] Flushing queued task 0 for executor
'default' of framework 201307061349-160088899-49663-3668-0000
I0706 13:49:37.176548 3700 exec.cpp:194] Executor registered on slave
201307061349-160088899-49663-3668-0
I0706 13:49:37.638224 3700 exec.cpp:258] Executor asked to run task '0'
I0706 13:49:37.407418 3701 hierarchical_allocator_process.hpp:568] Framework
201307061349-160088899-49663-3668-0000 filtered slave
201307061349-160088899-49663-3668-0 for 5secs
I0706 13:49:37.638458 3700 sched.cpp:427] Stopping framework
'201307061349-160088899-49663-3668-0000'
I0706 13:49:37.773614 3701 hierarchical_allocator_process.hpp:796] Filtered
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:37.889111 3700 master.cpp:447] Framework
201307061349-160088899-49663-3668-0000 disconnected
I0706 13:49:38.008587 3701 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 234.988923ms
I0706 13:49:38.239691 3701 hierarchical_allocator_process.hpp:411] Deactivated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:38.124341 3699 sched.cpp:177] New master at
[email protected]:49663
W0706 13:49:38.152547 3706 master.cpp:83] No whitelist given. Advertising
offers for all slaves
I0706 13:49:38.123862 3700 master.cpp:474] Giving framework
201307061349-160088899-49663-3668-0000 100ms to failover
I0706 13:49:38.705817 3700 master.cpp:675] Re-registering framework
201307061349-160088899-49663-3668-0000 at scheduler(84)@67.195.138.9:49663
I0706 13:49:38.816495 3700 master.cpp:694] Framework
201307061349-160088899-49663-3668-0000 failed over
I0706 13:49:38.932992 3703 hierarchical_allocator_process.hpp:381] Activated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.040487 3703 hierarchical_allocator_process.hpp:726] Offering
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:38.933066 3702 sched.cpp:222] Framework registered with
201307061349-160088899-49663-3668-0000
I0706 13:49:38.933017 3705 slave.cpp:1277] Updating framework
201307061349-160088899-49663-3668-0000 pid to scheduler(84)@67.195.138.9:49663
I0706 13:49:39.148131 3703 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 107.674774ms
I0706 13:49:39.148175 3700 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-2 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.474747 3703 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 15.587us
I0706 13:49:39.586299 3700 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.648720 3705 sched.cpp:427] Stopping framework
'201307061349-160088899-49663-3668-0000'
I0706 13:49:39.648758 3668 master.cpp:436] Master terminating
I0706 13:49:39.664374 3668 master.cpp:209] Shutting down master
I0706 13:49:39.664417 3703 slave.cpp:485] Slave asked to shut down by
[email protected]:49663
I0706 13:49:39.680294 3703 slave.cpp:1112] Asked to shut down framework
201307061349-160088899-49663-3668-0000 by [email protected]:49663
I0706 13:49:39.672441 3702 hierarchical_allocator_process.hpp:411] Deactivated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.672381 3668 master.hpp:317] Removing task 0 with resources
cpus=1; mem=256 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.688230 3703 slave.cpp:1137] Shutting down framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.712136 3703 slave.cpp:2328] Shutting down executor 'default' of
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.704324 3701 hierarchical_allocator_process.hpp:615] Recovered
cpus=1; mem=256 (total allocatable: cpus=1; mem=256; ports=[]; disk=0) on slave
201307061349-160088899-49663-3668-0 from framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.704257 3668 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-2 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.720125 3700 exec.cpp:323] Executor asked to shutdown
I0706 13:49:39.720140 3703 slave.cpp:1884] [email protected]:49663 exited
I0706 13:49:39.728133 3701 hierarchical_allocator_process.hpp:615] Recovered
cpus=2; mem=768; ports=[31000-32000]; disk=775878 (total allocatable: cpus=3;
mem=1024; ports=[31000-32000]; disk=775878) on slave
201307061349-160088899-49663-3668-0 from framework
201307061349-160088899-49663-3668-0000
W0706 13:49:39.751922 3703 slave.cpp:1887] Master disconnected! Waiting for a
new master to be elected
I0706 13:49:39.759949 3701 hierarchical_allocator_process.hpp:366] Removed
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.775794 3703 slave.cpp:440] Slave terminating
I0706 13:49:39.783817 3701 hierarchical_allocator_process.hpp:476] Removed
slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.791730 3703 slave.cpp:1112] Asked to shut down framework
201307061349-160088899-49663-3668-0000 by @0.0.0.0:0
W0706 13:49:39.807653 3703 slave.cpp:1133] Ignoring shutdown framework
201307061349-160088899-49663-3668-0000 because it is terminating
[ FAILED ] AllocatorTest/0.SchedulerFailover, where TypeParam =
mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter,
mesos::internal::master::allocator::DRFSorter> (7222 ms)
was (Author: bmahler):
Looks like this is still flaky on Jenkins:
[ RUN ] AllocatorTest/0.SchedulerFailover
I0706 13:49:32.603111 3700 master.cpp:230] Master started on 67.195.138.9:49663
I0706 13:49:32.713898 3700 master.cpp:245] Master ID:
201307061349-160088899-49663-3668
I0706 13:49:32.604032 3703 sched.cpp:177] New master at
[email protected]:49663
I0706 13:49:32.603664 3704 slave.cpp:113] Slave started on
92)@67.195.138.9:49663
W0706 13:49:32.825726 3699 master.cpp:83] No whitelist given. Advertising
offers for all slaves
I0706 13:49:32.825882 3705 hierarchical_allocator_process.hpp:305]
Initializing hierarchical allocator process with master :
[email protected]:49663
I0706 13:49:32.825920 3700 master.cpp:583] Elected as master!
I0706 13:49:33.040659 3704 slave.cpp:205] Slave resources: cpus=3; mem=1024;
ports=[31000-32000]; disk=775878
I0706 13:49:33.363317 3700 master.cpp:633] Registering framework
201307061349-160088899-49663-3668-0000 at scheduler(83)@67.195.138.9:49663
I0706 13:49:33.471230 3704 slave.cpp:529] New master detected at
[email protected]:49663
I0706 13:49:33.526826 3700 sched.cpp:222] Framework registered with
201307061349-160088899-49663-3668-0000
I0706 13:49:33.526926 3705 hierarchical_allocator_process.hpp:335] Added
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:33.534617 3704 slave.cpp:544] Postponing registration until
recovery is complete
I0706 13:49:33.534627 3703 status_update_manager.cpp:155] New master detected
at [email protected]:49663
I0706 13:49:33.650123 3705 hierarchical_allocator_process.hpp:704] No
resources available to allocate!
I0706 13:49:33.753705 3704 slave.cpp:390] Finished recovery
I0706 13:49:33.972802 3705 hierarchical_allocator_process.hpp:666] Performed
allocation for 0 slaves in 322.686119ms
I0706 13:49:34.080523 3699 master.cpp:962] Attempting to register slave on
vesta.apache.org at slave(92)@67.195.138.9:49663
I0706 13:49:34.199889 3699 master.cpp:1929] Adding slave
201307061349-160088899-49663-3668-0 at vesta.apache.org with cpus=3; mem=1024;
ports=[31000-32000]; disk=775878
I0706 13:49:34.260555 3706 hierarchical_allocator_process.hpp:704] No
resources available to allocate!
I0706 13:49:34.314430 3704 slave.cpp:589] Registered with master
[email protected]:49663; given slave ID 201307061349-160088899-49663-3668-0
I0706 13:49:34.433764 3706 hierarchical_allocator_process.hpp:666] Performed
allocation for 0 slaves in 173.257394ms
I0706 13:49:34.666087 3706 hierarchical_allocator_process.hpp:448] Added slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) with cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 (and cpus=3; mem=1024; ports=[31000-32000];
disk=775878 available)
I0706 13:49:34.780099 3706 hierarchical_allocator_process.hpp:726] Offering
cpus=3; mem=1024; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:34.903579 3706 hierarchical_allocator_process.hpp:686] Performed
allocation for slave 201307061349-160088899-49663-3668-0 in 123.5028ms
I0706 13:49:34.903635 3704 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-0 with resources cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.130395 3704 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.250018 3702 master.cpp:1543] Processing reply for offer
201307061349-160088899-49663-3668-0 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.359308 3702 master.hpp:305] Adding task 0 with resources
cpus=1; mem=256 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.476686 3702 master.cpp:1662] Launching task 0 of framework
201307061349-160088899-49663-3668-0000 with resources cpus=1; mem=256 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org)
I0706 13:49:35.588238 3702 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-0 with resources cpus=3; mem=1024;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:35.588278 3704 slave.cpp:739] Got assigned task 0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.588335 3699 hierarchical_allocator_process.hpp:525] Framework
201307061349-160088899-49663-3668-0000 left cpus=2; mem=768;
ports=[31000-32000]; disk=775878 unused on slave
201307061349-160088899-49663-3668-0
I0706 13:49:35.811238 3704 slave.cpp:837] Launching task 0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:35.929050 3699 hierarchical_allocator_process.hpp:726] Offering
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:36.047159 3704 paths.hpp:303] Created executor directory
'/tmp/AllocatorTest_0_SchedulerFailover_HBQWdJ/slaves/201307061349-160088899-49663-3668-0/frameworks/201307061349-160088899-49663-3668-0000/executors/default/runs/76dcfb35-84c8-48d3-949c-df1887fa5b49'
I0706 13:49:36.161496 3699 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 232.455392ms
I0706 13:49:36.161623 3705 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-1 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:36.276984 3704 slave.cpp:948] Queuing task '0' for executor
default of framework '201307061349-160088899-49663-3668-0000
I0706 13:49:36.277175 3706 exec.cpp:170] Executor started at:
executor(31)@67.195.138.9:49663 with pid 3668
I0706 13:49:36.499796 3705 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:36.615203 3704 slave.cpp:511] Successfully attached file
'/tmp/AllocatorTest_0_SchedulerFailover_HBQWdJ/slaves/201307061349-160088899-49663-3668-0/frameworks/201307061349-160088899-49663-3668-0000/executors/default/runs/76dcfb35-84c8-48d3-949c-df1887fa5b49'
I0706 13:49:36.845386 3705 master.cpp:1543] Processing reply for offer
201307061349-160088899-49663-3668-1 on slave
201307061349-160088899-49663-3668-0 (vesta.apache.org) for framework
201307061349-160088899-49663-3668-0000
tests/allocator_tests.cpp:674: Failure
Mock function called more times than expected - taking default action specified
at:
./tests/mesos.hpp:361:
Function call: resourcesUnused(@0x2b404401a478
201307061349-160088899-49663-3668-0000, @0x2b404401a458
201307061349-160088899-49663-3668-0, @0x2b404401a420 { cpus=2, mem=768,
ports=[31000-32000], disk=775878 }, @0x2b404401a410 16-byte object <00-00 00-00
40-2B 00-00 30-42 01-44 40-2B 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I0706 13:49:36.957567 3704 slave.cpp:1395] Got registration for executor
'default' of framework 201307061349-160088899-49663-3668-0000
I0706 13:49:37.065049 3705 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-1 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:37.065214 3701 hierarchical_allocator_process.hpp:525] Framework
201307061349-160088899-49663-3668-0000 left cpus=2; mem=768;
ports=[31000-32000]; disk=775878 unused on slave
201307061349-160088899-49663-3668-0
I0706 13:49:37.176506 3704 slave.cpp:1510] Flushing queued task 0 for executor
'default' of framework 201307061349-160088899-49663-3668-0000
I0706 13:49:37.176548 3700 exec.cpp:194] Executor registered on slave
201307061349-160088899-49663-3668-0
I0706 13:49:37.638224 3700 exec.cpp:258] Executor asked to run task '0'
I0706 13:49:37.407418 3701 hierarchical_allocator_process.hpp:568] Framework
201307061349-160088899-49663-3668-0000 filtered slave
201307061349-160088899-49663-3668-0 for 5secs
I0706 13:49:37.638458 3700 sched.cpp:427] Stopping framework
'201307061349-160088899-49663-3668-0000'
I0706 13:49:37.773614 3701 hierarchical_allocator_process.hpp:796] Filtered
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 for framework
201307061349-160088899-49663-3668-0000
I0706 13:49:37.889111 3700 master.cpp:447] Framework
201307061349-160088899-49663-3668-0000 disconnected
I0706 13:49:38.008587 3701 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 234.988923ms
I0706 13:49:38.239691 3701 hierarchical_allocator_process.hpp:411] Deactivated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:38.124341 3699 sched.cpp:177] New master at
[email protected]:49663
W0706 13:49:38.152547 3706 master.cpp:83] No whitelist given. Advertising
offers for all slaves
I0706 13:49:38.123862 3700 master.cpp:474] Giving framework
201307061349-160088899-49663-3668-0000 100ms to failover
I0706 13:49:38.705817 3700 master.cpp:675] Re-registering framework
201307061349-160088899-49663-3668-0000 at scheduler(84)@67.195.138.9:49663
I0706 13:49:38.816495 3700 master.cpp:694] Framework
201307061349-160088899-49663-3668-0000 failed over
I0706 13:49:38.932992 3703 hierarchical_allocator_process.hpp:381] Activated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.040487 3703 hierarchical_allocator_process.hpp:726] Offering
cpus=2; mem=768; ports=[31000-32000]; disk=775878 on slave
201307061349-160088899-49663-3668-0 to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:38.933066 3702 sched.cpp:222] Framework registered with
201307061349-160088899-49663-3668-0000
I0706 13:49:38.933017 3705 slave.cpp:1277] Updating framework
201307061349-160088899-49663-3668-0000 pid to scheduler(84)@67.195.138.9:49663
I0706 13:49:39.148131 3703 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 107.674774ms
I0706 13:49:39.148175 3700 master.hpp:327] Adding offer
201307061349-160088899-49663-3668-2 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.474747 3703 hierarchical_allocator_process.hpp:666] Performed
allocation for 1 slaves in 15.587us
I0706 13:49:39.586299 3700 master.cpp:1310] Sending 1 offers to framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.648720 3705 sched.cpp:427] Stopping framework
'201307061349-160088899-49663-3668-0000'
I0706 13:49:39.648758 3668 master.cpp:436] Master terminating
I0706 13:49:39.664374 3668 master.cpp:209] Shutting down master
I0706 13:49:39.664417 3703 slave.cpp:485] Slave asked to shut down by
[email protected]:49663
I0706 13:49:39.680294 3703 slave.cpp:1112] Asked to shut down framework
201307061349-160088899-49663-3668-0000 by [email protected]:49663
I0706 13:49:39.672441 3702 hierarchical_allocator_process.hpp:411] Deactivated
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.672381 3668 master.hpp:317] Removing task 0 with resources
cpus=1; mem=256 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.688230 3703 slave.cpp:1137] Shutting down framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.712136 3703 slave.cpp:2328] Shutting down executor 'default' of
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.704324 3701 hierarchical_allocator_process.hpp:615] Recovered
cpus=1; mem=256 (total allocatable: cpus=1; mem=256; ports=[]; disk=0) on slave
201307061349-160088899-49663-3668-0 from framework
201307061349-160088899-49663-3668-0000
I0706 13:49:39.704257 3668 master.hpp:337] Removing offer
201307061349-160088899-49663-3668-2 with resources cpus=2; mem=768;
ports=[31000-32000]; disk=775878 on slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.720125 3700 exec.cpp:323] Executor asked to shutdown
I0706 13:49:39.720140 3703 slave.cpp:1884] [email protected]:49663 exited
I0706 13:49:39.728133 3701 hierarchical_allocator_process.hpp:615] Recovered
cpus=2; mem=768; ports=[31000-32000]; disk=775878 (total allocatable: cpus=3;
mem=1024; ports=[31000-32000]; disk=775878) on slave
201307061349-160088899-49663-3668-0 from framework
201307061349-160088899-49663-3668-0000
W0706 13:49:39.751922 3703 slave.cpp:1887] Master disconnected! Waiting for a
new master to be elected
I0706 13:49:39.759949 3701 hierarchical_allocator_process.hpp:366] Removed
framework 201307061349-160088899-49663-3668-0000
I0706 13:49:39.775794 3703 slave.cpp:440] Slave terminating
I0706 13:49:39.783817 3701 hierarchical_allocator_process.hpp:476] Removed
slave 201307061349-160088899-49663-3668-0
I0706 13:49:39.791730 3703 slave.cpp:1112] Asked to shut down framework
201307061349-160088899-49663-3668-0000 by @0.0.0.0:0
W0706 13:49:39.807653 3703 slave.cpp:1133] Ignoring shutdown framework
201307061349-160088899-49663-3668-0000 because it is terminating
[ FAILED ] AllocatorTest/0.SchedulerFailover, where TypeParam =
mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter,
mesos::internal::master::allocator::DRFSorter> (7222 ms)
> AllocatorTest/0.SchedulerFailover is flaky.
> -------------------------------------------
>
> Key: MESOS-410
> URL: https://issues.apache.org/jira/browse/MESOS-410
> Project: Mesos
> Issue Type: Bug
> Reporter: Benjamin Mahler
> Assignee: Thomas Marshall
>
> Looks like there are some bad expectations in the SchedulerFailover test.
> [ RUN ] AllocatorTest/0.SchedulerFailover
> I0321 20:49:55.008021 3226 master.cpp:309] Master started on
> 67.195.138.60:33834
> I0321 20:49:55.008059 3226 master.cpp:324] Master ID:
> 201303212049-1015726915-33834-3147
> I0321 20:49:55.008726 3226 master.cpp:603] Elected as master!
> I0321 20:49:55.008412 3228 sched.cpp:182] New master at
> [email protected]:33834
> I0321 20:49:55.009618 3228 master.cpp:646] Registering framework
> 201303212049-1015726915-33834-3147-0000 at scheduler(63)@67.195.138.60:33834
> I0321 20:49:55.010125 3228 sched.cpp:217] Framework registered with
> 201303212049-1015726915-33834-3147-0000
> W0321 20:49:55.008816 3229 master.cpp:81] No whitelist given. Advertising
> offers for all slaves
> I0321 20:49:55.008859 3230 hierarchical_allocator_process.hpp:236]
> Initializing hierarchical allocator process with master :
> [email protected]:33834
> I0321 20:49:55.060097 3230 hierarchical_allocator_process.hpp:268] Added
> framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.065731 3230 hierarchical_allocator_process.hpp:668] No
> resources available to allocate!
> I0321 20:49:55.066246 3230 hierarchical_allocator_process.hpp:599] Performed
> allocation for 0 slaves in 517.48us
> I0321 20:49:55.008122 3224 slave.cpp:203] Slave started on
> 73)@67.195.138.60:33834
> I0321 20:49:55.067206 3224 slave.cpp:204] Slave resources: cpus=3; mem=1024;
> ports=[31000-32000]; disk=14036
> I0321 20:49:55.068222 3224 slave.cpp:453] New master detected at
> [email protected]:33834
> I0321 20:49:55.068403 3224 slave.cpp:377] Finished recovery
> I0321 20:49:55.069236 3224 master.cpp:968] Attempting to register slave on
> janus.apache.org at slave(73)@67.195.138.60:33834
> I0321 20:49:55.070163 3224 master.cpp:1224] Master now considering a slave
> at janus.apache.org:33834 as active
> I0321 20:49:55.070575 3224 master.cpp:1862] Adding slave
> 201303212049-1015726915-33834-3147-0 at janus.apache.org with cpus=3;
> mem=1024; ports=[31000-32000]; disk=14036
> I0321 20:49:55.072634 3224 slave.cpp:487] Registered with master; given
> slave ID 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.068428 3226 status_update_manager.cpp:132] New master
> detected at [email protected]:33834
> I0321 20:49:55.072762 3228 hierarchical_allocator_process.hpp:395] Added
> slave 201303212049-1015726915-33834-3147-0 (janus.apache.org) with cpus=3;
> mem=1024; ports=[31000-32000]; disk=14036 (and cpus=3; mem=1024;
> ports=[31000-32000]; disk=14036 available)
> I0321 20:49:55.074096 3228 hierarchical_allocator_process.hpp:660] Found
> available resources: cpus=3; mem=1024; ports=[31000-32000]; disk=14036 on
> slave 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.074628 3228 hierarchical_allocator_process.hpp:686] Offering
> cpus=3; mem=1024; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0 to framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.075227 3228 hierarchical_allocator_process.hpp:619] Performed
> allocation for slave 201303212049-1015726915-33834-3147-0 in 1.14ms
> I0321 20:49:55.075314 3224 master.hpp:309] Adding offer with resources
> cpus=3; mem=1024; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.076213 3224 master.cpp:1327] Sending 1 offers to framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.076750 3224 sched.cpp:282] Received 1 offers
> I0321 20:49:55.077636 3224 master.cpp:1534] Processing reply for offer
> 201303212049-1015726915-33834-3147-0 on slave
> 201303212049-1015726915-33834-3147-0 (janus.apache.org) for framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.077834 3224 master.hpp:289] Adding task with resources
> cpus=1; mem=256 on slave 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.078308 3224 master.cpp:1651] Launching task 0 of framework
> 201303212049-1015726915-33834-3147-0000 with resources cpus=1; mem=256 on
> slave 201303212049-1015726915-33834-3147-0 (janus.apache.org)
> I0321 20:49:55.078922 3224 master.hpp:318] Removing offer with resources
> cpus=3; mem=1024; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.078999 3229 slave.cpp:599] Got assigned task 0 for framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.079066 3230 hierarchical_allocator_process.hpp:471] Framework
> 201303212049-1015726915-33834-3147-0000 left cpus=2; mem=768;
> ports=[31000-32000]; disk=14036 unused on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.081300 3229 paths.hpp:302] Created executor directory
> '/tmp/AllocatorTest_0_SchedulerFailover_oWPFSh/slaves/201303212049-1015726915-33834-3147-0/frameworks/201303212049-1015726915-33834-3147-0000/executors/default/runs/da91e171-2172-4e06-b425-1aa1e8522aa7'
> I0321 20:49:55.122453 3229 slave.cpp:436] Successfully attached file
> '/tmp/AllocatorTest_0_SchedulerFailover_oWPFSh/slaves/201303212049-1015726915-33834-3147-0/frameworks/201303212049-1015726915-33834-3147-0000/executors/default/runs/da91e171-2172-4e06-b425-1aa1e8522aa7'
> I0321 20:49:55.122535 3225 exec.cpp:170] Executor started at:
> executor(20)@67.195.138.60:33834 with pid 3147
> I0321 20:49:55.123455 3225 slave.cpp:1058] Got registration for executor
> 'default' of framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.124008 3225 slave.cpp:1133] Flushing queued tasks for
> framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.124099 3229 exec.cpp:194] Executor registered on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.125076 3229 exec.cpp:258] Executor asked to run task '0'
> I0321 20:49:55.125663 3227 sched.cpp:422] Stopping framework
> '201303212049-1015726915-33834-3147-0000'
> I0321 20:49:55.126713 3227 master.cpp:488] Framework
> 201303212049-1015726915-33834-3147-0000 disconnected
> I0321 20:49:55.127213 3227 master.cpp:500] Giving framework
> 201303212049-1015726915-33834-3147-0000 500.00ms to failover
> I0321 20:49:55.127316 3223 hierarchical_allocator_process.hpp:359]
> Deactivated framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.127428 3226 sched.cpp:182] New master at
> [email protected]:33834
> I0321 20:49:55.128818 3226 master.cpp:681] Re-registering framework
> 201303212049-1015726915-33834-3147-0000 at scheduler(64)@67.195.138.60:33834
> I0321 20:49:55.162433 3226 master.cpp:700] Framework
> 201303212049-1015726915-33834-3147-0000 failed over
> I0321 20:49:55.163038 3226 sched.cpp:217] Framework registered with
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.163110 3228 slave.cpp:968] Updating framework
> 201303212049-1015726915-33834-3147-0000 pid to
> scheduler(64)@67.195.138.60:33834
> I0321 20:49:55.163147 3224 hierarchical_allocator_process.hpp:327] Activated
> framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.164475 3224 hierarchical_allocator_process.hpp:660] Found
> available resources: cpus=2; mem=768; ports=[31000-32000]; disk=14036 on
> slave 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.164984 3224 hierarchical_allocator_process.hpp:686] Offering
> cpus=2; mem=768; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0 to framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.165602 3224 hierarchical_allocator_process.hpp:599] Performed
> allocation for 1 slaves in 1.15ms
> I0321 20:49:55.165699 3230 master.hpp:309] Adding offer with resources
> cpus=2; mem=768; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.166571 3230 master.cpp:1327] Sending 1 offers to framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.167109 3230 sched.cpp:282] Received 1 offers
> I0321 20:49:55.167677 3225 sched.cpp:422] Stopping framework
> '201303212049-1015726915-33834-3147-0000'
> I0321 20:49:55.168128 3225 master.cpp:488] Framework
> 201303212049-1015726915-33834-3147-0000 disconnected
> I0321 20:49:55.168639 3225 master.cpp:500] Giving framework
> 201303212049-1015726915-33834-3147-0000 500.00ms to failover
> I0321 20:49:55.178027 3225 master.hpp:318] Removing offer with resources
> cpus=2; mem=768; ports=[31000-32000]; disk=14036 on slave
> 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.168725 3229 hierarchical_allocator_process.hpp:359]
> Deactivated framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.199956 3229 hierarchical_allocator_process.hpp:544] Recovered
> cpus=2; mem=768; ports=[31000-32000]; disk=14036 (total allocatable: cpus=2;
> mem=768; ports=[31000-32000]; disk=14036) on slave
> 201303212049-1015726915-33834-3147-0 from framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.678827 3227 master.cpp:1259] Framework failover timeout,
> removing framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.699990 3227 master.hpp:300] Removing task with resources
> cpus=1; mem=256 on slave 201303212049-1015726915-33834-3147-0
> I0321 20:49:55.705976 3227 hierarchical_allocator_process.hpp:544] Recovered
> cpus=1; mem=256 (total allocatable: cpus=3; mem=1024; ports=[31000-32000];
> disk=14036) on slave 201303212049-1015726915-33834-3147-0 from framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.700172 3223 slave.cpp:901] Asked to shut down framework
> 201303212049-1015726915-33834-3147-0000 by [email protected]:33834
> I0321 20:49:55.706676 3223 slave.cpp:906] Shutting down framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.707144 3223 slave.cpp:1693] Shutting down executor 'default'
> of framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.707645 3223 slave.cpp:386] Slave terminating
> I0321 20:49:55.708091 3223 slave.cpp:901] Asked to shut down framework
> 201303212049-1015726915-33834-3147-0000 by @0.0.0.0:0
> I0321 20:49:55.708566 3223 slave.cpp:906] Shutting down framework
> 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.709998 3223 slave.cpp:1693] Shutting down executor 'default'
> of framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.710511 3223 master.cpp:537] Slave
> 201303212049-1015726915-33834-3147-0(janus.apache.org) disconnected
> I0321 20:49:55.710978 3223 master.cpp:542] Removing disconnected slave
> 201303212049-1015726915-33834-3147-0(janus.apache.org) because it is not
> checkpointing!
> I0321 20:49:55.707731 3228 status_update_manager.cpp:233] Closing status
> update streams for framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.712024 3228 status_update_manager.cpp:233] Closing status
> update streams for framework 201303212049-1015726915-33834-3147-0000
> I0321 20:49:55.711609 3147 master.cpp:477] Master terminating
> ../../src/tests/allocator_tests.cpp:642: Failure
> Actual function call count doesn't match EXPECT_CALL(exec, shutdown(_))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
