[MESOS-9422] DiskQuotaTest.DiskUsageExceedsQuota is flaky.

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.6.1
• Component/s: test
• Labels: flaky-test
• Assignee: Unassigned
• Reporter: Chun-Hung Hsiao
• Created: 29/Nov/18 03:15
• Updated: 29/Nov/18 03:27

Description

Observed a flake on this test in our internal CI for Mesos 1.6.x (configuration: mac-SSL):

I1128 16:53:56.318218 104120320 executor.cpp:687] Forked command at 7880
I1128 16:53:56.318235 174346240 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to the agent
I1128 16:53:56.318398 175955968 slave.cpp:5778] Forwarding the update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to master@10.0.49.4:56289
I1128 16:53:56.318568 175955968 slave.cpp:5671] Task status update manager successfully handled status update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.318614 175955968 slave.cpp:5687] Sending acknowledgement for status update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to executor(1)@10.0.49.4:56508
I1128 16:53:56.318817 173809664 master.cpp:8332] Status update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 from agent f9320cbf-2553-4ce5-9cbd-e8deeea16b79-S0 at slave(37)@10.0.49.4:56289 (Jenkinss-Mac-mini.local)
I1128 16:53:56.318872 173809664 master.cpp:8389] Forwarding status update TASK_STARTING (Status UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.318972 173809664 master.cpp:10842] Updating the state of task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
I1128 16:53:56.319315 174882816 sched.cpp:1022] Scheduler::statusUpdate took 203974ns
I1128 16:53:56.319394 177029120 slave.cpp:5286] Handling status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 from executor(1)@10.0.49.4:56508
I1128 16:53:56.319638 173273088 master.cpp:6188] Processing ACKNOWLEDGE call for status fd841117-e5f5-433e-a173-d8b3d5eda7b8 for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 (default) at scheduler-f8c2522b-fbc4-4444-add8-a781092521a0@10.0.49.4:56289 on agent f9320cbf-2553-4ce5-9cbd-e8deeea16b79-S0
I1128 16:53:56.320201 175955968 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.320471 173273088 slave.cpp:4522] Task status update manager successfully handled status update acknowledgement (UUID: fd841117-e5f5-433e-a173-d8b3d5eda7b8) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.320839 174882816 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.320909 174882816 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to the agent
I1128 16:53:56.320989 173273088 slave.cpp:5778] Forwarding the update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to master@10.0.49.4:56289
I1128 16:53:56.321148 173273088 slave.cpp:5671] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.321182 173273088 slave.cpp:5687] Sending acknowledgement for status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 to executor(1)@10.0.49.4:56508
I1128 16:53:56.321211 173809664 master.cpp:8332] Status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 from agent f9320cbf-2553-4ce5-9cbd-e8deeea16b79-S0 at slave(37)@10.0.49.4:56289 (Jenkinss-Mac-mini.local)
I1128 16:53:56.321247 173809664 master.cpp:8389] Forwarding status update TASK_RUNNING (Status UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.321383 173809664 master.cpp:10842] Updating the state of task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1128 16:53:56.321599 174346240 sched.cpp:1022] Scheduler::statusUpdate took 86327ns
I1128 16:53:56.321799 175419392 master.cpp:6188] Processing ACKNOWLEDGE call for status 759fb8db-a319-4409-a0c8-238484295637 for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000 (default) at scheduler-f8c2522b-fbc4-4444-add8-a781092521a0@10.0.49.4:56289 on agent f9320cbf-2553-4ce5-9cbd-e8deeea16b79-S0
I1128 16:53:56.321969 176492544 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:53:56.322121 174346240 slave.cpp:4522] Task status update manager successfully handled status update acknowledgement (UUID: 759fb8db-a319-4409-a0c8-238484295637) for task 5656ebcb-ed5e-4c0d-96f6-532d88e78c27 of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:54:12.829758 174882816 hierarchical.cpp:2415] Filtered offer with cpus:1; mem:896; disk:1023; ports:[31000-32000] on agent f9320cbf-2553-4ce5-9cbd-e8deeea16b79-S0 for role * of framework f9320cbf-2553-4ce5-9cbd-e8deeea16b79-0000
I1128 16:54:12.829865 174882816 hierarchical.cpp:1520] Performed allocation for 1 agents in 545752ns
../../src/tests/disk_quota_tests.cpp:240: Failure
Failed to wait 15secs for status2
../../src/tests/disk_quota_tests.cpp:225: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
Expected: to be called 3 times
Actual: called twice - unsatisfied and active

Note that from the above logs, it seemed the task command, which is dd, was never executed at all.