tests: output_spec: fix "throttles shell-command output greater than ~10KB" #10854

blueyed · 2019-08-26T11:54:37Z

Latest failure for that test:

[ RUN      ] shell command :! throttles shell-command output greater than ~10KB: 
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
486.75 ms ERR
test/functional/ui/screen.lua:587: Failed to match any screen lines.
Expected (anywhere): "
%."
Actual:
  |1096: foo                                         |
  |1097: foo                                         |
  |1098: foo                                         |
  |1099: foo                                         |
  |[...]                                             |
  |                                                  |
  |{3:-- TERMINAL --}                                    |
stack traceback:
	test/functional/ui/screen.lua:587: in function '_wait'
	test/functional/ui/screen.lua:370: in function 'expect'
	test/functional/ui/output_spec.lua:61: in function <test/functional/ui/output_spec.lua:52>

(https://travis-ci.org/neovim/neovim/jobs/594313045#L6551)

…~10KB" Flaky on osx. Looks like all the output is there already. [ ERROR ] test/functional/ui/output_spec.lua @ 52: shell command :! throttles shell-command output greater than ~10KB test/functional/ui/screen.lua:581: Failed to match any screen lines. Expected (anywhere): " %." Actual: |29997: foo | |29998: foo | |29999: foo | |30000: foo | | | |{UNEXPECTED foreground = tonumber('0x000002'):Press ENTER or type command to continue}{1: } | |{3:-- TERMINAL --} | stack traceback: test/functional/ui/screen.lua:581: in function '_wait' test/functional/ui/screen.lua:368: in function 'expect' test/functional/ui/output_spec.lua:57: in function <test/functional/ui/output_spec.lua:52>

blueyed · 2019-08-26T12:37:23Z

Failed:

Repeating all tests (run 92 of 200) . . .
[----------] Global test environment setup.
[----------] Running tests from test/functional/ui/output_spec.lua
[ RUN      ] shell command :! displays output without LF/EOF. #4646 #4569 #3772: 13.97 ms OK
[ RUN      ] shell command :! throttles shell-command output greater than ~10KB: 
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
ERR
test/functional/ui/screen.lua:581: Failed to match any screen lines.
Expected (anywhere): "
%."
Actual:
  |572: foo                                          |
  |573: foo                                          |
  |574: foo                                          |
  |575: foo                                          |
  |                                                  |
  |                                                  |
  |{3:-- TERMINAL --}                                    |
stack traceback:
	test/functional/ui/screen.lua:581: in function '_wait'
	test/functional/ui/screen.lua:368: in function 'expect'
	test/functional/ui/output_spec.lua:57: in function <test/functional/ui/output_spec.lua:52>
[----------] 2 tests from test/functional/ui/output_spec.lua (306.00 ms total)

How/why does it fail after ~300ms when it should wait for 20s though?
(https://github.com/blueyed/neovim/blob/7ada6209e142816f4d5cbc3de3ac1cc314824968/test/functional/ui/output_spec.lua#L57)

blueyed · 2019-08-26T13:09:48Z

The failure looks like it matched the ".", but then tested again afterwards, where it was removed (temporarily), and failure_after_success gets set then..

blueyed · 2019-08-26T13:23:10Z

Alternatively/additionally something like this might be useful, to display a dot always:

diff --git i/src/nvim/os/shell.c w/src/nvim/os/shell.c
index 19d199f4d..79f6602eb 100644
--- i/src/nvim/os/shell.c
+++ w/src/nvim/os/shell.c
@@ -390,7 +390,7 @@ static bool out_data_decide_throttle(size_t size)
   static uint64_t   started     = 0;  // Start time of the current throttle.
   static size_t     received    = 0;  // Bytes observed since last throttle.
   static size_t     visit       = 0;  // "Pulse" count of the current throttle.
-  static char       pulse_msg[] = { ' ', ' ', ' ', '\0' };
+  static char       pulse_msg[] = { '.', ' ', ' ', '\0' };

   if (!size) {
     bool previous_decision = (visit > 0);
@@ -418,7 +418,6 @@ static bool out_data_decide_throttle(size_t size)
   size_t tick = (visit % 20 == 0)
                 ? 3  // Force all dots "..." on last visit.
                 : (visit % 4);
-  pulse_msg[0] = (tick == 0) ? ' ' : '.';
   pulse_msg[1] = (tick == 0 || 1 == tick) ? ' ' : '.';
   pulse_msg[2] = (tick == 0 || 1 == tick || 2 == tick) ? ' ' : '.';
   if (visit == 1) {

blueyed · 2019-08-26T13:24:19Z

With retry:

Repeating all tests (run 97 of 200) . . .
[----------] Global test environment setup.
[----------] Running tests from test/functional/ui/output_spec.lua
[ RUN      ] shell command :! displays output without LF/EOF. #4646 #4569 #3772: 15.37 ms OK
[ RUN      ] shell command :! throttles shell-command output greater than ~10KB: 
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
ERR
test/functional/helpers.lua:403: 
retry() attempts: 4
test/functional/ui/screen.lua:581: Failed to match any screen lines.
Expected (anywhere): "
%."
Actual:
  |29997: foo                                        |
  |29998: foo                                        |
  |29999: foo                                        |
  |30000: foo                                        |
  |                                                  |
  |{UNEXPECTED foreground = tonumber('0x000002'):Press ENTER or type command to continue}{1: }          |
  |{3:-- TERMINAL --}                                    |
stack traceback:
	test/functional/helpers.lua:403: in function 'retry'
	test/functional/ui/output_spec.lua:58: in function <test/functional/ui/output_spec.lua:53>

blueyed · 2019-08-26T13:25:17Z

The main issue here appears to be though that any should (optionally) not check for later changes I guess.

Pulse every 0.2s only, displaying first dot always ([1]). This makes `!yes` look much better (less busy) - although that might have been intentional?!. 1: neovim#10854 (comment)

blueyed · 2019-08-26T15:13:49Z

Latest:

Repeating all tests (run 97 of 200) . . .
[----------] Global test environment setup.
[----------] Running tests from test/functional/ui/output_spec.lua
[ RUN      ] shell command :! displays output without LF/EOF. #4646 #4569 #3772: 15.37 ms OK
[ RUN      ] shell command :! throttles shell-command output greater than ~10KB: 
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
ERR
test/functional/helpers.lua:403: 
retry() attempts: 4
test/functional/ui/screen.lua:581: Failed to match any screen lines.
Expected (anywhere): "
%."
Actual:
  |29997: foo                                        |
  |29998: foo                                        |
  |29999: foo                                        |
  |30000: foo                                        |
  |                                                  |
  |{UNEXPECTED foreground = tonumber('0x000002'):Press ENTER or type command to continue}{1: }          |
  |{3:-- TERMINAL --}                                    |
stack traceback:
	test/functional/helpers.lua:403: in function 'retry'
	test/functional/ui/output_spec.lua:58: in function <test/functional/ui/output_spec.lua:53>
[----------] 2 tests from test/functional/ui/output_spec.lua (21824.55 ms total)
[----------] Global test environment teardown.
------------------------------------------------------------------------------
$NVIM_LOG_FILE: /Users/travis/build/neovim/neovim/build/.nvimlog
(empty)
------------------------------------------------------------------------------
[==========] 2 tests from 1 test file ran. (21824.71 ms total)

Suspicious that's around 95 always (some global state kept when repeating?!).
At least it took > 20s now.

blueyed · 2019-08-26T15:14:40Z

The main issue here appears to be though that any should (optionally) not check for later changes I guess.

I think there should be something that does not fail due to later changes.
/cc @bfredl

justinmk · 2019-08-26T15:29:06Z

The main issue here appears to be though that any should (optionally) not check for later changes I guess.

I think there should be something that does not fail due to later changes.

That is the intended semantics of any so I think it's fine to just change any to work like that.

bfredl · 2019-08-26T15:47:02Z

That is the intended semantics of any so I think it's fine to just change any to work like that.

The meaning of any is to check that a string is visible on a part of the grid instead of the entire grid. The question of checking a intermediate state instead of the final state is completely orthogonal to that, and should be a separate flag. I do not see any value in needlessly entangling the two. In particular external state will now become final with full grid or no grid at all, but suddenly instead intermediate if partial grid is used.

blueyed · 2019-08-26T15:50:59Z

@bfredl
Should we have a general flag then that allows to pass with intermediate states?
(the existing intermediate is something else, right?)

bfredl · 2019-08-26T15:55:32Z

yes, maybe the existing intermediate flag name is a bit unfortunate, it really means unchanged_with_intermediate, which I probably thought was to long.

blueyed · 2019-08-27T00:34:29Z

Last:

Repeating all tests (run 158 of 200) . . .
[----------] Global test environment setup.
[----------] Running tests from test/functional/ui/output_spec.lua
[ RUN      ] shell command :! displays output without LF/EOF. #4646 #4569 #3772: 44.05 ms OK
[ RUN      ] shell command :! throttles shell-command output greater than ~10KB: 
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
warning: Screen changes were received after the expected state. This indicates
indeterminism in the test. Try adding screen:expect(...) (or wait()) between
asynchronous (feed(), nvim_input()) and synchronous API calls.
  - Use screen:redraw_debug() to investigate; it may find relevant intermediate
    states that should be added to the test to make it more robust.
  - If the purpose of the test is to assert state after some user input sent
    with feed(), adding screen:expect() before the feed() will help to ensure
    the input is sent when Nvim is in a predictable state. This is preferable
    to wait(), for being closer to real user interaction.
  - wait() can trigger redraws and consequently generate more indeterminism.
    Try removing wait().
      
ERR
test/functional/helpers.lua:403: 
retry() attempts: 4
test/functional/ui/screen.lua:581: Failed to match any screen lines.
Expected (anywhere): "
%."
Actual:
  |3456789                                           |
  |30000: 0123456789012345678901234567890123456789012|
  |34567890123456789012345678901234567890123456789012|
  |3456789                                           |
  |                                                  |
  |{UNEXPECTED foreground = tonumber('0x000002'):Press ENTER or type command to continue}{1: }          |
  |{3:-- TERMINAL --}                                    |
stack traceback:
	test/functional/helpers.lua:403: in function 'retry'
	test/functional/ui/output_spec.lua:58: in function <test/functional/ui/output_spec.lua:53>
[----------] 2 tests from test/functional/ui/output_spec.lua (21723.76 ms total)

blueyed · 2019-08-27T00:45:36Z

yes, maybe the existing intermediate flag name is a bit unfortunate, it really means unchanged_with_intermediate, which I probably thought was to long.

Currently there is:

  if flags.intermediate and flags.unchanged then
    error("Choose only one of 'intermediate' and 'unchanged', not both")
  end

I.e. we could have the current behavior be described by specifying unchanged=true, intermediate=true (instead of renaming it to unchanged_with_intermediate - this could be used internally then only).
And this test here would then use only intermediate=true maybe.

But using unchanged_with_intermediate explicitly might be better. And then the new one (here) could be named intermediate_ok or similar.

However, it seems that it appears to be still flaky given what intermediate_ok=true would do (last failure).

bfredl · 2019-08-27T10:13:37Z

Not sure I like unchanged=true, intermediate=true, I think there should be one flag for unchanged_with_intermediate (where the supplied state still should be the final one), but it could have a shorter name. Then another flag for when the supplied state itself is allowed to be intermediate, I was thinking of calling it allow_failure_after rather or something (because the state doesn't have to be intermediate, we just allow failed states after it).

justinmk · 2019-08-27T10:25:07Z

unchanged=x, intermediate=x makes the most sense to me.

unchanged=true, intermediate=true means "final state looks the same, ignore temporary changes"
unchanged=true, intermediate=false means "final state and intermediate states must not change"
unchanged=false, intermediate=false is the existing/default behavior
unchanged=false, intermediate=true is not implemented, probably not needed, so just guard it with an assert.

Adding more flags would mean more combinations, most of which are nonsense.

bfredl · 2019-08-27T10:29:29Z

But then rather that unchanged=false, intermediate=true doesn't mean anything to start with, because intermediate is a sub-flag that modifies unchanged behaivor.

bfredl · 2019-08-27T10:34:29Z

Adding more flags would mean more combinations, most of which are nonsense.

But the alternative never was to add "more flags", rather just rename the intermediate flag.

blueyed · 2019-08-27T11:21:08Z

But the alternative never was to add "more flags", rather just rename the intermediate flag.

One new flag would be needed though (allow_failure_after).

But it does not seem to be the problem with #10854 (comment) after all - it should only be a warning after all, not cause it to fail. (still good to have a way to suppress this warning then)

bfredl · 2019-08-27T11:40:12Z

One new flag would be needed though (allow_failure_after).

This was about unchanged_with_intermediate=true versus unchanged=true, intermediate=true (versus doing nothing about it) only. The former does not need "more flags" than the later, as a flag is only renamed. Whether allow_failure_after should be added is a separate decision, which depends only on if we want that particular functionality or not.

justinmk · 2019-08-27T12:17:46Z

Doesn't unchanged=x, intermediate=x allow us to support allow_failure_after without actually adding the allow_failure_after flag?

bfredl · 2019-08-27T12:21:43Z

No, none of unchanged=x, intermediate=x is about changing the meaning of the asserted state. They still expect the final state to be the supplied one, and only change what is allowed/expected before that. Cramming in allow_failure_after as a special combination of those seems like flag tetris to me. It is an entire new behavior, and should have a dedicated flag if supported.

justinmk · 2019-08-27T12:52:15Z

any_intermediate ?

bfredl · 2019-08-27T13:00:28Z

maybe, but allow_failure_after sounds less ambiguous to me. Though maybe "allow failure" reads as an oxymoron, perhaps allow_nonmatching_after ?

blueyed added 2 commits August 26, 2019 13:47

TEMP: Travis: repeat on osx

ec5b4cf

blueyed added the test label Aug 26, 2019

TEMP: only run_functionaltests

3ce6251

marvim added the WIP label Aug 26, 2019

fixup! TEMP: Travis: repeat on osx

7ada620

rebuild

eb7e398

use retry

1e8449a

blueyed mentioned this pull request Aug 26, 2019

Revisit out_data_decide_throttle #10855

Merged

Screen:_wait: skip setting failure_after_success with expected.any

398827a

back to child_session.feed_data, more data

7593696

test: old, without retry, with debug

72973d0

dundargoc removed the WIP label Feb 7, 2023

dundargoc changed the title ~~[WIP] tests: output_spec: fix "throttles shell-command output greater than ~10KB"~~ tests: output_spec: fix "throttles shell-command output greater than ~10KB" Apr 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests: output_spec: fix "throttles shell-command output greater than ~10KB" #10854

tests: output_spec: fix "throttles shell-command output greater than ~10KB" #10854

blueyed commented Aug 26, 2019 •

edited

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

justinmk commented Aug 26, 2019

bfredl commented Aug 26, 2019

blueyed commented Aug 26, 2019

bfredl commented Aug 26, 2019

blueyed commented Aug 27, 2019

blueyed commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019 •

edited

bfredl commented Aug 27, 2019

bfredl commented Aug 27, 2019

blueyed commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019

bfredl commented Aug 27, 2019

tests: output_spec: fix "throttles shell-command output greater than ~10KB" #10854

Are you sure you want to change the base?

tests: output_spec: fix "throttles shell-command output greater than ~10KB" #10854

Conversation

blueyed commented Aug 26, 2019 • edited

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

blueyed commented Aug 26, 2019

justinmk commented Aug 26, 2019

bfredl commented Aug 26, 2019

blueyed commented Aug 26, 2019

bfredl commented Aug 26, 2019

blueyed commented Aug 27, 2019

blueyed commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019 • edited

bfredl commented Aug 27, 2019

bfredl commented Aug 27, 2019

blueyed commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019

bfredl commented Aug 27, 2019

justinmk commented Aug 27, 2019

bfredl commented Aug 27, 2019

blueyed commented Aug 26, 2019 •

edited

justinmk commented Aug 27, 2019 •

edited