Benjamin Mahler created MESOS-413:
-------------------------------------
Summary: AllocatorTest/0.TaskFinished test has bad expectations.
Key: MESOS-413
URL: https://issues.apache.org/jira/browse/MESOS-413
Project: Mesos
Issue Type: Bug
Reporter: Benjamin Mahler
Assignee: Thomas Marshall
>From Jenkins:
[ RUN ] AllocatorTest/0.TaskFinished
I0321 01:10:26.339004 31935 master.cpp:309] Master started on
67.195.138.60:52923
I0321 01:10:26.339076 31935 master.cpp:324] Master ID:
201303210110-1015726915-52923-31915
I0321 01:10:26.339607 31941 slave.cpp:203] Slave started on
79)@67.195.138.60:52923
I0321 01:10:26.339993 31940 sched.cpp:182] New master at
[email protected]:52923
I0321 01:10:26.339789 31936 hierarchical_allocator_process.hpp:236]
Initializing hierarchical allocator process with master :
[email protected]:52923
I0321 01:10:26.339880 31935 master.cpp:603] Elected as master!
I0321 01:10:26.339987 31941 slave.cpp:204] Slave resources: cpus=3; mem=1024;
ports=[31000-32000]; disk=14049
W0321 01:10:26.339649 31938 master.cpp:81] No whitelist given. Advertising
offers for all slaves
I0321 01:10:26.341651 31935 master.cpp:646] Registering framework
201303210110-1015726915-52923-31915-0000 at scheduler(69)@67.195.138.60:52923
I0321 01:10:26.342483 31941 slave.cpp:453] New master detected at
[email protected]:52923
I0321 01:10:26.343711 31942 sched.cpp:217] Framework registered with
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.343752 31940 hierarchical_allocator_process.hpp:268] Added
framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.345178 31940 hierarchical_allocator_process.hpp:668] No
resources available to allocate!
I0321 01:10:26.345821 31940 hierarchical_allocator_process.hpp:599] Performed
allocation for 0 slaves in 645.16us
I0321 01:10:26.344215 31941 slave.cpp:377] Finished recovery
I0321 01:10:26.344229 31935 status_update_manager.cpp:131] New master detected
at [email protected]:52923
I0321 01:10:26.346981 31936 master.cpp:968] Attempting to register slave on
janus.apache.org at slave(79)@67.195.138.60:52923
I0321 01:10:26.347973 31936 master.cpp:1224] Master now considering a slave at
janus.apache.org:52923 as active
I0321 01:10:26.348474 31936 master.cpp:1862] Adding slave
201303210110-1015726915-52923-31915-0 at janus.apache.org with cpus=3;
mem=1024; ports=[31000-32000]; disk=14049
I0321 01:10:26.349043 31936 slave.cpp:487] Registered with master; given slave
ID 201303210110-1015726915-52923-31915-0
I0321 01:10:26.349172 31940 hierarchical_allocator_process.hpp:395] Added slave
201303210110-1015726915-52923-31915-0 (janus.apache.org) with cpus=3; mem=1024;
ports=[31000-32000]; disk=14049 (and cpus=3; mem=1024; ports=[31000-32000];
disk=14049 available)
I0321 01:10:26.349931 31940 hierarchical_allocator_process.hpp:660] Found
available resources: cpus=3; mem=1024; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:26.350442 31940 hierarchical_allocator_process.hpp:686] Offering
cpus=3; mem=1024; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0 to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.351016 31940 hierarchical_allocator_process.hpp:619] Performed
allocation for slave 201303210110-1015726915-52923-31915-0 in 1.09ms
I0321 01:10:26.351059 31936 master.hpp:309] Adding offer with resources cpus=3;
mem=1024; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:26.352747 31936 master.cpp:1327] Sending 1 offers to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.353261 31941 sched.cpp:282] Received 1 offers
I0321 01:10:26.353957 31936 master.cpp:1534] Processing reply for offer
201303210110-1015726915-52923-31915-0 on slave
201303210110-1015726915-52923-31915-0 (janus.apache.org) for framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.354317 31936 master.hpp:289] Adding task with resources cpus=1;
mem=256 on slave 201303210110-1015726915-52923-31915-0
I0321 01:10:26.354735 31936 master.cpp:1651] Launching task 0 of framework
201303210110-1015726915-52923-31915-0000 with resources cpus=1; mem=256 on
slave 201303210110-1015726915-52923-31915-0 (janus.apache.org)
I0321 01:10:26.355278 31941 slave.cpp:599] Got assigned task 0 for framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.356691 31941 paths.hpp:302] Created executor directory
'/tmp/AllocatorTest_0_TaskFinished_m8lWIA/slaves/201303210110-1015726915-52923-31915-0/frameworks/201303210110-1015726915-52923-31915-0000/executors/default/runs/3156fec3-00d6-4c84-963a-f34345a974dd'
I0321 01:10:26.355288 31936 master.hpp:289] Adding task with resources cpus=1;
mem=256 on slave 201303210110-1015726915-52923-31915-0
I0321 01:10:26.357118 31941 slave.cpp:436] Successfully attached file
'/tmp/AllocatorTest_0_TaskFinished_m8lWIA/slaves/201303210110-1015726915-52923-31915-0/frameworks/201303210110-1015726915-52923-31915-0000/executors/default/runs/3156fec3-00d6-4c84-963a-f34345a974dd'
I0321 01:10:26.357209 31939 exec.cpp:170] Executor started at:
executor(25)@67.195.138.60:52923 with pid 31915
I0321 01:10:26.357311 31936 master.cpp:1651] Launching task 1 of framework
201303210110-1015726915-52923-31915-0000 with resources cpus=1; mem=256 on
slave 201303210110-1015726915-52923-31915-0 (janus.apache.org)
I0321 01:10:26.358922 31939 slave.cpp:1033] Got registration for executor
'default' of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.359464 31936 master.hpp:318] Removing offer with resources
cpus=3; mem=1024; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:26.359555 31940 hierarchical_allocator_process.hpp:471] Framework
201303210110-1015726915-52923-31915-0000 left cpus=1; mem=512;
ports=[31000-32000]; disk=14049 unused on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:26.359930 31939 slave.cpp:1108] Flushing queued tasks for framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.361453 31939 slave.cpp:599] Got assigned task 1 for framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.362232 31939 slave.cpp:737] Sending task '1' to executor
'default' of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.359987 31935 exec.cpp:194] Executor registered on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:26.364218 31935 exec.cpp:258] Executor asked to run task '0'
I0321 01:10:26.364758 31935 exec.cpp:258] Executor asked to run task '1'
I0321 01:10:26.365463 31935 exec.cpp:382] Executor sending status update for
task 0 in state TASK_RUNNING
I0321 01:10:26.366636 31935 exec.cpp:382] Executor sending status update for
task 1 in state TASK_RUNNING
I0321 01:10:26.366665 31941 slave.cpp:1216] Handling status update TASK_RUNNING
from task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.367187 31941 slave.cpp:1263] Forwarding status update
TASK_RUNNING from task 0 of framework 201303210110-1015726915-52923-31915-0000
to the status update manager
I0321 01:10:26.367769 31938 status_update_manager.cpp:253] Received status
update TASK_RUNNING from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.367775 31941 slave.cpp:1216] Handling status update TASK_RUNNING
from task 1 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.369221 31938 status_update_manager.cpp:402] Creating
StatusUpdate stream for task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.370157 31938 status_update_manager.hpp:314] Handling UPDATE for
status update TASK_RUNNING from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.370636 31938 status_update_manager.cpp:288] Forwarding status
update TASK_RUNNING from task 0 of framework
201303210110-1015726915-52923-31915-0000 to the master at
[email protected]:52923
I0321 01:10:26.369699 31941 slave.cpp:1263] Forwarding status update
TASK_RUNNING from task 1 of framework 201303210110-1015726915-52923-31915-0000
to the status update manager
I0321 01:10:26.371270 31937 master.cpp:1086] Status update from
(734)@67.195.138.60:52923: task 0 of framework
201303210110-1015726915-52923-31915-0000 is now in state TASK_RUNNING
I0321 01:10:26.371739 31941 slave.cpp:1325] Sending ACK for status update
TASK_RUNNING from task 0 of framework 201303210110-1015726915-52923-31915-0000
to executor executor(25)@67.195.138.60:52923
I0321 01:10:26.371743 31942 status_update_manager.cpp:253] Received status
update TASK_RUNNING from task 1 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.372236 31936 sched.cpp:327] Received status update TASK_RUNNING
from task 0 of framework 201303210110-1015726915-52923-31915-0000 from
slave(79)@67.195.138.60:52923
I0321 01:10:26.372889 31937 exec.cpp:289] Executor received ACK for status
update of task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.374078 31942 status_update_manager.cpp:402] Creating
StatusUpdate stream for task 1 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.375207 31936 sched.cpp:360] Sending ACK for status update
TASK_RUNNING from task 0 of framework 201303210110-1015726915-52923-31915-0000
to slave(79)@67.195.138.60:52923
I0321 01:10:26.377210 31936 slave.cpp:991] Got acknowledgement of status update
for task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.376005 31942 status_update_manager.hpp:314] Handling UPDATE for
status update TASK_RUNNING from task 1 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.378142 31942 status_update_manager.cpp:288] Forwarding status
update TASK_RUNNING from task 1 of framework
201303210110-1015726915-52923-31915-0000 to the master at
[email protected]:52923
I0321 01:10:26.378666 31942 status_update_manager.cpp:313] Received status
update acknowledgement for task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.378701 31941 master.cpp:1086] Status update from
(734)@67.195.138.60:52923: task 1 of framework
201303210110-1015726915-52923-31915-0000 is now in state TASK_RUNNING
I0321 01:10:26.378705 31940 slave.cpp:1325] Sending ACK for status update
TASK_RUNNING from task 1 of framework 201303210110-1015726915-52923-31915-0000
to executor executor(25)@67.195.138.60:52923
I0321 01:10:26.379886 31942 status_update_manager.hpp:314] Handling ACK for
status update TASK_RUNNING from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.380398 31935 sched.cpp:327] Received status update TASK_RUNNING
from task 1 of framework 201303210110-1015726915-52923-31915-0000 from
slave(79)@67.195.138.60:52923
I0321 01:10:26.380852 31941 exec.cpp:289] Executor received ACK for status
update of task 1 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.382591 31935 sched.cpp:360] Sending ACK for status update
TASK_RUNNING from task 1 of framework 201303210110-1015726915-52923-31915-0000
to slave(79)@67.195.138.60:52923
I0321 01:10:26.383736 31938 slave.cpp:991] Got acknowledgement of status update
for task 1 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:26.384263 31938 status_update_manager.cpp:313] Received status
update acknowledgement for task 1 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:26.384610 31938 status_update_manager.hpp:314] Handling ACK for
status update TASK_RUNNING from task 1 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.341601 31938 hierarchical_allocator_process.hpp:660] Found
available resources: cpus=1; mem=512; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:27.341691 31938 hierarchical_allocator_process.hpp:686] Offering
cpus=1; mem=512; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0 to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.342162 31938 hierarchical_allocator_process.hpp:599] Performed
allocation for 1 slaves in 581.90us
I0321 01:10:27.342226 31936 master.hpp:309] Adding offer with resources cpus=1;
mem=512; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:27.342991 31936 master.cpp:1327] Sending 1 offers to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.343497 31940 sched.cpp:282] Received 1 offers
I0321 01:10:27.344004 31940 master.cpp:1534] Processing reply for offer
201303210110-1015726915-52923-31915-1 on slave
201303210110-1015726915-52923-31915-0 (janus.apache.org) for framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.344472 31940 master.hpp:318] Removing offer with resources
cpus=1; mem=512; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:27.344563 31935 hierarchical_allocator_process.hpp:471] Framework
201303210110-1015726915-52923-31915-0000 left cpus=1; mem=512;
ports=[31000-32000]; disk=14049 unused on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:27.345899 31935 hierarchical_allocator_process.hpp:497] Framework
201303210110-1015726915-52923-31915-0000 filtered slave
201303210110-1015726915-52923-31915-0 for 1.00secs
I0321 01:10:27.344043 31937 exec.cpp:382] Executor sending status update for
task 0 in state TASK_FINISHED
I0321 01:10:27.347534 31937 slave.cpp:1216] Handling status update
TASK_FINISHED from task 0 of framework 201303210110-1015726915-52923-31915-0000
../../src/tests/allocator_tests.cpp:1139: Failure
Mock function called more times than expected - returning directly.
Function call: resourcesChanged(@0x2ad15c001ed8
201303210110-1015726915-52923-31915-0000, @0x2ad15c001eb8 default,
@0x2ad15c001e80 { cpus=1, mem=256 })
Expected: to be called twice
Actual: called 3 times - over-saturated and active
I0321 01:10:27.347615 31937 slave.cpp:1263] Forwarding status update
TASK_FINISHED from task 0 of framework 201303210110-1015726915-52923-31915-0000
to the status update manager
I0321 01:10:27.347980 31937 status_update_manager.cpp:253] Received status
update TASK_FINISHED from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.348350 31937 status_update_manager.hpp:314] Handling UPDATE for
status update TASK_FINISHED from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.348825 31937 status_update_manager.cpp:288] Forwarding status
update TASK_FINISHED from task 0 of framework
201303210110-1015726915-52923-31915-0000 to the master at
[email protected]:52923
I0321 01:10:27.349365 31937 master.cpp:1086] Status update from
(734)@67.195.138.60:52923: task 0 of framework
201303210110-1015726915-52923-31915-0000 is now in state TASK_FINISHED
I0321 01:10:27.349441 31939 slave.cpp:1325] Sending ACK for status update
TASK_FINISHED from task 0 of framework 201303210110-1015726915-52923-31915-0000
to executor executor(25)@67.195.138.60:52923
I0321 01:10:27.349831 31937 master.hpp:300] Removing task with resources
cpus=1; mem=256 on slave 201303210110-1015726915-52923-31915-0
I0321 01:10:27.349843 31938 sched.cpp:327] Received status update TASK_FINISHED
from task 0 of framework 201303210110-1015726915-52923-31915-0000 from
slave(79)@67.195.138.60:52923
I0321 01:10:27.352282 31938 sched.cpp:360] Sending ACK for status update
TASK_FINISHED from task 0 of framework 201303210110-1015726915-52923-31915-0000
to slave(79)@67.195.138.60:52923
I0321 01:10:27.352726 31938 slave.cpp:991] Got acknowledgement of status update
for task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:27.350308 31936 exec.cpp:289] Executor received ACK for status
update of task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:27.350852 31940 hierarchical_allocator_process.hpp:544] Recovered
cpus=1; mem=256 (total allocatable: cpus=2; mem=768; ports=[31000-32000];
disk=14049) on slave 201303210110-1015726915-52923-31915-0 from framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.353274 31935 status_update_manager.cpp:313] Received status
update acknowledgement for task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.354802 31935 status_update_manager.hpp:314] Handling ACK for
status update TASK_FINISHED from task 0 of framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:27.355379 31935 status_update_manager.cpp:433] Cleaning up status
update stream for task 0 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:27.594573 31942 monitor.cpp:206] Publishing resource usage for
executor 'default' of framework '201303210110-1015726915-52923-31915-0000'
I0321 01:10:27.671926 31942 monitor.cpp:206] Publishing resource usage for
executor 'default' of framework '201303210110-1015726915-52923-31915-0000'
I0321 01:10:28.228677 31942 monitor.cpp:206] Publishing resource usage for
executor 'default' of framework '201303210110-1015726915-52923-31915-0000'
I0321 01:10:28.342949 31942 hierarchical_allocator_process.hpp:660] Found
available resources: cpus=2; mem=768; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:28.343039 31942 hierarchical_allocator_process.hpp:686] Offering
cpus=2; mem=768; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0 to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.343487 31942 hierarchical_allocator_process.hpp:599] Performed
allocation for 1 slaves in 576.24us
I0321 01:10:28.343554 31936 master.hpp:309] Adding offer with resources cpus=2;
mem=768; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:28.344316 31936 master.cpp:1327] Sending 1 offers to framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.344831 31938 sched.cpp:282] Received 1 offers
I0321 01:10:28.345420 31937 sched.cpp:422] Stopping framework
'201303210110-1015726915-52923-31915-0000'
I0321 01:10:28.345793 31936 master.cpp:774] Asked to unregister framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.346261 31936 master.hpp:300] Removing task with resources
cpus=1; mem=256 on slave 201303210110-1015726915-52923-31915-0
I0321 01:10:28.346273 31935 slave.cpp:901] Asked to shut down framework
201303210110-1015726915-52923-31915-0000 by [email protected]:52923
I0321 01:10:28.347188 31935 slave.cpp:906] Shutting down framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.346782 31936 master.hpp:318] Removing offer with resources
cpus=2; mem=768; ports=[31000-32000]; disk=14049 on slave
201303210110-1015726915-52923-31915-0
I0321 01:10:28.346315 31940 hierarchical_allocator_process.hpp:359] Deactivated
framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.348675 31940 hierarchical_allocator_process.hpp:544] Recovered
cpus=1; mem=256 (total allocatable: cpus=1; mem=256; ports=[]; disk=0) on slave
201303210110-1015726915-52923-31915-0 from framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.349171 31940 hierarchical_allocator_process.hpp:544] Recovered
cpus=2; mem=768; ports=[31000-32000]; disk=14049 (total allocatable: cpus=3;
mem=1024; ports=[31000-32000]; disk=14049) on slave
201303210110-1015726915-52923-31915-0 from framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.349663 31940 hierarchical_allocator_process.hpp:312] Removed
framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.347652 31935 slave.cpp:1645] Shutting down executor 'default' of
framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.350584 31936 exec.cpp:321] Executor asked to shutdown
I0321 01:10:28.350594 31935 status_update_manager.cpp:232] Closing status
update streams for framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.351163 31941 slave.cpp:386] Slave terminating
I0321 01:10:28.351544 31935 status_update_manager.cpp:433] Cleaning up status
update stream for task 1 of framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.352043 31941 slave.cpp:901] Asked to shut down framework
201303210110-1015726915-52923-31915-0000 by @0.0.0.0:0
I0321 01:10:28.353875 31941 slave.cpp:906] Shutting down framework
201303210110-1015726915-52923-31915-0000
I0321 01:10:28.354343 31941 slave.cpp:1645] Shutting down executor 'default' of
framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.354922 31941 status_update_manager.cpp:232] Closing status
update streams for framework 201303210110-1015726915-52923-31915-0000
I0321 01:10:28.354938 31937 master.cpp:537] Slave
201303210110-1015726915-52923-31915-0(janus.apache.org) disconnected
I0321 01:10:28.356609 31937 master.cpp:542] Removing disconnected slave
201303210110-1015726915-52923-31915-0(janus.apache.org) because it is not
checkpointing!
I0321 01:10:28.357228 31915 master.cpp:477] Master terminating
I0321 01:10:28.358006 31915 master.cpp:283] Shutting down master
[ FAILED ] AllocatorTest/0.TaskFinished, where TypeParam =
mesos::internal::master::HierarchicalAllocatorProcess<mesos::internal::master::DRFSorter,
mesos::internal::master::DRFSorter> (2020 ms)
--
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
