[MESOS-9495] Test `MasterTest.CreateVolumesV1AuthorizationFailure` is flaky.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.5.0, 1.5.1, 1.6.0, 1.6.1, 1.7.0
• Fix Version/s: 1.8.0
• Component/s: test
• Labels: flaky-test resource-management
• Sprint: Resource Mgmt R9 Sprint 37
• Story Points: 1
• Assignee: Benjamin Mahler
• Reporter: Chun-Hung Hsiao
• Created: 20/Dec/18 22:17
• Updated: 09/Jan/19 23:45
• Resolved: 09/Jan/19 23:45

Description

I1219 22:45:59.578233 26107 slave.cpp:1884] Will retry registration in 2.10132ms if necessary
I1219 22:45:59.578615 26107 master.cpp:6125] Received register agent message from slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal)
I1219 22:45:59.578830 26107 master.cpp:3871] Authorizing agent with principal 'test-principal'
I1219 22:45:59.578975 26107 master.cpp:6183] Authorized registration of agent at slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal)
I1219 22:45:59.579039 26107 master.cpp:6294] Registering agent at slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal) with id 85292fcc-b698-4377-9faa-f76b0ccd4ee5-S0
I1219 22:45:59.579540 26107 registrar.cpp:495] Applied 1 operations in 143852ns; attempting to update the registry
I1219 22:45:59.580102 26109 registrar.cpp:552] Successfully updated the registry in 510208ns
I1219 22:45:59.580312 26109 master.cpp:6342] Admitted agent 85292fcc-b698-4377-9faa-f76b0ccd4ee5-S0 at slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal)
I1219 22:45:59.580968 26111 slave.cpp:1884] Will retry registration in 23.973874ms if necessary
I1219 22:45:59.581447 26111 slave.cpp:1486] Registered with master master@172.16.10.13:35739; given agent ID 85292fcc-b698-4377-9faa-f76b0ccd4ee5-S0
...
I1219 22:45:59.580950 26109 master.cpp:6391] Registered agent 85292fcc-b698-4377-9faa-f76b0ccd4ee5-S0 at slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal) with disk(reservations: [(STATIC,role1)]):1024; cpus:2; mem:6796; ports:[31000-32000]
I1219 22:45:59.583326 26109 master.cpp:6125] Received register agent message from slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal)
I1219 22:45:59.583524 26109 master.cpp:3871] Authorizing agent with principal 'test-principal'
...
W1219 22:45:59.584242 26109 master.cpp:6175] Refusing registration of agent at slave(463)@172.16.10.13:35739 (ip-172-16-10-13.ec2.internal): Authorization failure: Authorizer failure
...
I1219 22:45:59.586944 26113 http.cpp:1185] HTTP POST for /master/api/v1 from 172.16.10.13:47412
I1219 22:45:59.587129 26113 http.cpp:682] Processing call CREATE_VOLUMES
/home/centos/workspace/mesos/Mesos_CI-build/FLAG/CMake/label/mesos-ec2-centos-7/mesos/src/tests/master_tests.cpp:9386: Failure
Mock function called more times than expected - returning default value.
    Function call: authorized(@0x7f5066524720 48-byte object <D8-BF 4F-72 50-7F 00-00 00-00 00-00 00-00 00-00 07-00 00-00 00-00 00-00 10-4E 02-48 50-7F 00-00 E0-4C 02-48 50-7F 00-00 06-00 00-00 50-7F 00-00>)
          Returns: Abandoned
         Expected: to be called once
           Actual: called twice - over-saturated and active
I1219 22:45:59.587761 26113 master.cpp:3811] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"id1","principal":"test-principal"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"role1","type":"STATIC"}],"scalar":{"value":64.0},"type":"SCALAR"}]'
...
/home/centos/workspace/mesos/Mesos_CI-build/FLAG/CMake/label/mesos-ec2-centos-7/mesos/src/tests/master_tests.cpp:9398: Failure
Failed to wait 15secs for response

This is because we authorize the retried registration before dropping it.

Full log: mesos-ec2-centos-7-CMake.Mesos.MasterTest.CreateVolumesV1AuthorizationFailure-badrun.txt