One thing I don't understand, with a patch like:

        }, {
                should:            "only return once status is no longer
running or pending",
                withAPIDelay:      2 * time.Second,
-               withClientWait:    "6s",
+               withClientWait:    "7s",
                withClientQueryID: validActionId,
-               withAPITimeout:    4 * time.Second,
+               withAPITimeout:    4100 * time.Millisecond,
                withTags:          tagsForIdPrefix(validActionId,
validActionTagString),

I see the test take 4s longer than if I do:
        }, {
                should:            "only return once status is no longer
running or pending",
                withAPIDelay:      2 * time.Second,
                withClientWait:    "6s",
                withClientQueryID: validActionId,
-               withAPITimeout:    4 * time.Second,
+               withAPITimeout:    3900 * time.Millisecond,
                withTags:          tagsForIdPrefix(validActionId,
validActionTagString),
                withAPIResponse: []params.ActionResult{{

I wonder if there is something causing us to cycle for >1 APITimeout
sleeps. (like if we *just* miss the timeout in the 2s tick, we end up
waiting an entire new cycle.)

I really don't understand why there is a full 4s difference, though.


On Wed, Mar 28, 2018 at 10:59 AM, John Meinel <email address hidden>
wrote:

> It seems to fail reliably with this change:
> diff --git a/cmd/juju/action/showoutput_test.go
> b/cmd/juju/action/showoutput_test.go
> index 3d073c4..00ee500 100644
> --- a/cmd/juju/action/showoutput_test.go
> +++ b/cmd/juju/action/showoutput_test.go
> @@ -127,7 +127,7 @@ timing:
>                 withAPIDelay:      2 * time.Second,
>                 withClientWait:    "6s",
>                 withClientQueryID: validActionId,
> -               withAPITimeout:    4 * time.Second,
> +               withAPITimeout:    4010 * time.Millisecond,
>                 withTags:          tagsForIdPrefix(validActionId,
> validActionTagString),
>                 withAPIResponse: []params.ActionResult{{
>                         Status: "running",
>
> So just adding 10ms is enough to cause the test to fail.
>
> Digging through the code, we seem to have some hard-coded very long times:
>
>
> func GetActionResult(api APIClient, requestedId string, wait *time.Timer)
> (params.ActionResult, error) {
>
>     // tick every two seconds, to delay the loop timer.
>     // TODO(fwereade): 2016-03-17 lp:1558657
>     tick := time.NewTimer(2 * time.Second)
>
>     return timerLoop(api, requestedId, wait, tick)
> }
> ...
> func timerLoop(api APIClient, requestedId string, wait, tick *time.Timer)
> (params.ActionResult, error) {
>  ...
>         case _ = <-tick.C:
>             tick.Reset(2 * time.Second)
>         }
>     }
> }
>
> so a lot of the code is hard-coded to step on a 2-second real-world cycle.
>
> At 18s real-world time to run the test, it seems pretty poor. (wastes a
> lot of pre-commit check time, just sitting idle, etc.)
>
>
> On Wed, Mar 28, 2018 at 10:29 AM, John Meinel <email address hidden>
> wrote:
>
>> The test seems a bit suspicious. It has an "withAPIDelay" of 2 seconds,
>> "withAPITimeout" of 4 seconds, and "ClientWait" of "6s" which I presume is
>> also 6 seconds. If API Delay is before we finish connecting, and API
>> Timeout is before the API returns, and ClientWait is exact time before the
>> client returns, how do we know for sure whether 6s comes before or after
>> 4+2s ?
>>
>> And why are we spending 18s mostly asleep in this test. Do we really need
>> real-world sleep times? Couldn't we do 200ms/400ms/600ms just as easily?
>>
>>
>> On Wed, Mar 28, 2018 at 10:23 AM, John Meinel <email address hidden>
>> wrote:
>>
>>> This happened twice in a row:
>>> http://ci.jujucharms.com/job/github-merge-juju/273/testRepor
>>> t/github/com_juju_juju_cmd_juju_action/TestPackage/
>>>
>>> it seems it should be looked at soon.
>>>
>>>
>>> On Wed, Mar 28, 2018 at 7:52 AM, John A Meinel <email address hidden>
>>> wrote:
>>>
>>>> Public bug reported:
>>>>
>>>> http://ci.jujucharms.com/job/github-merge-
>>>> juju/272/testReport/junit/github/com_juju_juju_cmd_juju_acti
>>>> on/TestPackage/
>>>>
>>>> ----------------------------------------------------------------------
>>>> FAIL: showoutput_test.go:59: ShowOutputSuite.TestRun
>>>>
>>>> test 0 (model flag -m): should handle wait-time formatting errors
>>>> test 0 (model flag --model): should handle wait-time formatting errors
>>>> test 1 (model flag -m): should timeout if result never comes
>>>> test 1 (model flag --model): should timeout if result never comes
>>>> test 2 (model flag -m): should pass api error through properly
>>>> test 2 (model flag --model): should pass api error through properly
>>>> test 3 (model flag -m): should fail with no tag matches
>>>> test 3 (model flag --model): should fail with no tag matches
>>>> test 4 (model flag -m): should fail with no results
>>>> test 4 (model flag --model): should fail with no results
>>>> test 5 (model flag -m): should error correctly with multiple results
>>>> test 5 (model flag --model): should error correctly with multiple
>>>> results
>>>> test 6 (model flag -m): should pass through an error from the API server
>>>> test 6 (model flag --model): should pass through an error from the API
>>>> server
>>>> test 7 (model flag -m): should only return once status is no longer
>>>> running or pending
>>>> test 7 (model flag --model): should only return once status is no
>>>> longer running or pending
>>>> showoutput_test.go:274:
>>>>     testRunHelper(
>>>>         c, s,
>>>>         makeFakeClient(
>>>>             t.withAPIDelay,
>>>>             t.withAPITimeout,
>>>>             t.withTags,
>>>>             t.withAPIResponse,
>>>>             params.ActionsByNames{},
>>>>             t.withAPIError),
>>>>         t.expectedErr,
>>>>         t.expectedOutput,
>>>>         t.withClientWait,
>>>>         t.withClientQueryID,
>>>>         modelFlag,
>>>>     )
>>>> showoutput_test.go:303:
>>>>     c.Check(err, gc.ErrorMatches, expectedErr)
>>>> ... value = nil
>>>> ... regex string = "test timed out before wait time"
>>>> ... Error value is nil
>>>>
>>>> test 8 (model flag -m): should pretty-print action output
>>>> test 8 (model flag --model): should pretty-print action output
>>>> test 9 (model flag -m): should pretty-print action output with no
>>>> completed time
>>>> test 9 (model flag --model): should pretty-print action output with no
>>>> completed time
>>>> test 10 (model flag -m): should pretty-print action output with no
>>>> enqueued time
>>>> test 10 (model flag --model): should pretty-print action output with no
>>>> enqueued time
>>>> test 11 (model flag -m): should pretty-print action output with no
>>>> started time
>>>> test 11 (model flag --model): should pretty-print action output with no
>>>> started time
>>>> test 12 (model flag -m): should set an appropriate timer and wait, get
>>>> a result
>>>> test 12 (model flag --model): should set an appropriate timer and wait,
>>>> get a result
>>>> OOPS: 8 passed, 1 FAILED
>>>>
>>>> ** Affects: juju
>>>>      Importance: Medium
>>>>          Status: Triaged
>>>>
>>>>
>>>> ** Tags: actions intermittent-failure
>>>>
>>>> --
>>>> You received this bug notification because you are subscribed to the bug
>>>> report.
>>>> https://bugs.launchpad.net/bugs/1759461
>>>>
>>>> Title:
>>>>   intermittent failure github.com/juju/juju/cmd/juju/action
>>>>   ShowOutputSuite.TestRun
>>>>
>>>> To manage notifications about this bug go to:
>>>> https://bugs.launchpad.net/juju/+bug/1759461/+subscriptions
>>>>
>>>
>>>
>>
>