Skip to content

Make test resilient to timing issues#1375

Merged
bsideup merged 6 commits into
masterfrom
fix-flapping-test
Jul 16, 2019
Merged

Make test resilient to timing issues#1375
bsideup merged 6 commits into
masterfrom
fix-flapping-test

Conversation

@rnorth

@rnorth rnorth commented Apr 9, 2019

Copy link
Copy Markdown
Member

No description provided.

@rnorth rnorth requested review from bsideup and kiview as code owners April 9, 2019 10:42
@bsideup

bsideup commented Apr 9, 2019

Copy link
Copy Markdown
Member

Hmm....

.withCommand("/bin/sh", "-c", "echo -n 'stdout' && echo -n 'stderr' 1>&2")

&& here should guarantee that stderr will follow after stdout. It looks more like a bug to me that the test is failing from time to time

@dmarkhas

Copy link
Copy Markdown
Contributor

I also fixed this test in #1345 since it was failing for me sporadically (even on my local machine) , are you sure docker-java logContainerCmd guarantees order?

@bsideup

bsideup commented Apr 10, 2019

Copy link
Copy Markdown
Member

It must be. I think we need to investigate it further, I'm afraid there is a bug

@rnorth

rnorth commented Apr 15, 2019

Copy link
Copy Markdown
Member Author

I think it's actually down to the flush decision in the shell (sh). Because the test is not running with a TTY apparently. With TTY, stdout is line-buffered; without TTY, stdout is fully buffered (and we'd be at the mercy of the timing of the shell's decision to flush.

Have a look at this (I've annotated for clarity):

bash-3.2$ while true; do
> docker run alpine /bin/sh -c "echo -n 'stdout' && echo -n 'stderr' 1>&2"
> echo
> sleep 0.1
> done
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stderrstdout   <--
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stdoutstderr
stderrstdout   <--
stdoutstderr
stdoutstderr
stderrstdout
stdoutstderr
...

Interestingly if we repeat this docker run with -t then the results come through perfectly ordered all the time. I'm not quite sure I understand this completely; echo -n ought to not be sending the newline characters that flush the stdout buffers. Regardless, this is the effect!

I guess we could modify this test to just use a TTY 🤔...

@bsideup

bsideup commented Apr 15, 2019

Copy link
Copy Markdown
Member

@rnorth
😱 TIL!
I wonder if this was the reason of flakiness of the log waiting strategy with some containers...

I support the idea of running this test with TTY, at least for the.... demo purpose :D Let's just put a comment above it about the flushing issue

@rnorth

rnorth commented Apr 15, 2019

Copy link
Copy Markdown
Member Author

Ergh, enabling TTY in these tests does something bizarre:

The three assertions results for the tests involving getLogs():

            '' does not equal expected 'stderr'

            'derr' does not equal expected 'stdout
stderr'

            'derr' does not equal expected 'stdout'

I think it's fair to say that there is a bug with getLogs() (or the data flow to it) when TTY is enabled!

@rnorth

rnorth commented May 7, 2019

Copy link
Copy Markdown
Member Author

@bsideup given that enabling TTY does even worse things for the log order, would you be OK for us to merge this as-is?

@bsideup

bsideup commented May 7, 2019

Copy link
Copy Markdown
Member

@rnorth I have really bad feeling about hiding this bug :(
But if we're not going to fix it, let's at least create a test for the order and mark it as ignored?

@bsideup bsideup added this to the next milestone Jul 16, 2019
@bsideup bsideup merged commit 03ba4c8 into master Jul 16, 2019
@delete-merged-branch delete-merged-branch Bot deleted the fix-flapping-test branch July 16, 2019 12:52
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants