https://bugs.winehq.org/show_bug.cgi?id=56459
Bug ID: 56459 Summary: Inconsistent and Unexpected I/O flush behavior Product: Wine Version: 9.4 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: msvcrt Assignee: wine-bugs@winehq.org Reporter: renatopereyra@google.com Distribution: ---
While recently debugging a Proton issue [1], I discovered odd I/O flushing behavior. Redirecting stderr/stdout to a file would cause most of intel-steam-stdout-255710.log in [1] to be empty. The contents of that file were critical to root-cause the issue and not having them made it much more difficult to debug. There were prints to stderr that directly explained what was going wrong and I had inadvertently hidden these by redirecting I/O "to preserve it" across multiple debugging runs.
To debug this I/O issue, I wrote a trivial Windows app that logs out to stderr and is configurable to cover multiple corner cases. I was able to reproduce the exact game behavior and a lot more other weirdness. I tested unmodified Wine 8.0, 9.0, and 9.4, as well as Proton 8.0 and Experimental (I will reach out to Proton devs independently). I found a total of 7 possible flushing outcomes and only 2 of those expected/good IMHO. In a lot of cases prints would just flat out completely be missing. There were also other cases where only partial data would ever flush out.
I've uploaded all my test results and test app to [2]. I'm unable to make the drive fully public per my organization's policies so please request access.
Notes regarding the data sheet: - While the test app supports multiple options (see README in [2]), the data sheet only includes a subset. Options omitted in the spreadsheet appeared to have no impact on the flush behavior. - The minimum set of states required to reach each specific possible flushing outcome is color-coded.
[1] https://github.com/ValveSoftware/Proton/issues/7529 [2] https://drive.google.com/drive/folders/14pWGcywUMtoc9z3QmHXNGbLq5Sdg3ICG?res...
https://bugs.winehq.org/show_bug.cgi?id=56459
renatopereyra@google.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |renatopereyra@google.com
https://bugs.winehq.org/show_bug.cgi?id=56459
Eric Pouech eric.pouech@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |eric.pouech@gmail.com
--- Comment #1 from Eric Pouech eric.pouech@gmail.com --- Did you test your program on windows, so that we can really tell what's wrong or right? That's IMO the first thing to do (see below).
Two global comments: - most of potential issues are likely not really about "flushing" but around: 1) (file) handle inheritance. Wine and Proton 9.0 have a bunch of changes regarding how they are inherited. Esp. handling GUI processes (as opposed to CUI processes) where Wine's behavior now closer mimics Windows. And GUI processes (like your test program) don't inherit console nor std file handles (unless explicitely told to) 2) several operations (like console creation / deletion, killing process...) happen to close handles (to the underlying object, which could even no longer be available). But your tests still expect some internal buffers to be flushed under these circonstances.
To move forward, could you please update your tests with: - running your test under windows and mark where there's a difference from Wine 9.0. It's very likely that your expectation would be closer to what Wine 8.0 was doing, unfortunately, it's not exactly how Windows behave. - when testing on Unix, you should also consider two cases: A) running from the Unix shell B) running from a windows-like console (using wineconsole) Results in B) should (that's the theory) be identical to Windows (if, not, it's a bug). Results in A) have no equivalent under Windows, so we had to make compromises between the two worlds, yet we have more flexibility on what's possible or not.
Depending on the outcome, it's likely we could open different tickets for different tests (as they could concern rather different part in Wine).
TIA
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #2 from renatopereyra@google.com --- Thanks for taking a look! I appreciate your help.
To move forward, could you please update your tests with:
- running your test under windows and mark where there's a difference from
Wine 9.0.
I updated the spreadsheet with outcomes from wineconsole and Windows. I found that wineconsole behaved the same as running Wine from a Linux terminal but Windows behaved a but differently, which seems like a bug. I highlighted the differences with red text.
most of potential issues are likely not really about "flushing" but around:
- (file) handle inheritance...
- several operations... happen to close handles...
Based on my testing on Windows, I think this is true in cases where there is no output written out anywhere at all (therefore, I renamed "no-flush" with "no-output" in the spreadsheet). However, there are cases in which Windows behaves similarly to Wine/wineconsole in principle but, in Windows, the characters are always flushed completely and at the time that they are written, rather than flushed in 4096-byte blocks like Wine does. In these cases, the results make me think that there really is a flushing problem.
- when testing on Unix, you should also consider two cases:
A) running from the Unix shell ... Results in A) have no equivalent under Windows, so we had to make compromises between the two worlds, yet we have more flexibility on what's possible or not.
My hope is that, when a process is invoked directly from the Linux terminal, we:
1. Independently ensure that any printfs are flushed out to the Linux terminal, regardless of whether they _also_ make it out to the wineconsole.
2. When a process is invoked through a Linux terminal, I/O redirection is processed by the Linux shell rather than Wine. In these cases Wine would behave as if there had been no I/O redirection requested. By extension, this would mean that I/O redirection only works like Windows does when used within wineconsole.
Combining #1 and #2 would mean that we can always get all output from a Windows program on the Linux side, regardless of Windows-style semantics, but only when a program is invoked from the Linux terminal. I'm not sure if this would break anything elsewhere but I think this would help developers while debugging because any errors logged by apps are always visible. Thoughts? Is this possible/sensible?
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #3 from Eric Pouech eric.pouech@gmail.com ---
I updated the spreadsheet with outcomes from wineconsole and Windows. I found that wineconsole behaved the same as running Wine from a Linux terminal but Windows behaved a but differently, which seems like a bug. I highlighted the differences with red text.
Thanks for taking care of this. I'll look into this.
My hope is that, when a process is invoked directly from the Linux terminal, we:
- Independently ensure that any printfs are flushed out to the Linux
terminal, regardless of whether they _also_ make it out to the wineconsole.
- When a process is invoked through a Linux terminal, I/O redirection is
processed by the Linux shell rather than Wine. In these cases Wine would behave as if there had been no I/O redirection requested. By extension, this would mean that I/O redirection only works like Windows does when used within wineconsole.
Combining #1 and #2 would mean that we can always get all output from a Windows program on the Linux side, regardless of Windows-style semantics, but only when a program is invoked from the Linux terminal. I'm not sure if this would break anything elsewhere but I think this would help developers while debugging because any errors logged by apps are always visible. Thoughts? Is this possible/sensible?
you may want to try: ./wine [[your exec and args]] < /dev/null 2>&1 | cat - this will ensure that no (windows) console is created (as none of fd 0,1,2 is mapped to a unix tty), but all output is redirected to linux terminal (I supposed you didn't need input from terminal in your program)
https://bugs.winehq.org/show_bug.cgi?id=56459
Eric Pouech eric.pouech@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|UNCONFIRMED |ASSIGNED Ever confirmed|0 |1
--- Comment #4 from Eric Pouech eric.pouech@gmail.com --- submitted https://gitlab.winehq.org/wine/wine/-/merge_requests/5462 that should take care of the buffering with 4096 bytes of stderr.
Note: letting stderr be always unbuffered (esp. when redirected to a file) is only supported by Windows on ucrtbase, and in recent versions of it (win7/8 and early Win10) let the buffering be in place.
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #5 from renatopereyra@google.com --- Thanks for debugging this, Eric! I'm sorry I took a while to get back to you.
./wine [[your exec and args]] < /dev/null 2>&1 | cat -
This worked locally whenever the app does not have a console. 1) Is there a way to get the output to (also) print to the Linux side even when there is a console? 2 It seems a bit unsafe to rely on this long-term. Is there or could there be some kind of test in Wine that protects this kind of use/behavior?
submitted https://gitlab.winehq.org/wine/wine/-/merge_requests/5462 that should take care of the buffering with 4096 bytes of stderr.
I rebuilt the test app I shared but had it print to stdout instead of stderr. On Windows, when there was no console allocated, I found that if the prints came from a subprocess, they were always routed to stderr, even if the subprocess was supposedly printing to stdout. If the prints were done in the process called from the Windows command prompt, the output would go to stdout as expected.
It seems you already found this but, to confirm, I found that stdout appears buffered in a 4096-byte buffer. This meant that subprocess prints were never buffered (since they came in on stderr) but prints from the main process did get buffered.
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #6 from renatopereyra@google.com --- I sent my comment too soon. I forgot to mention two more things.
I also tested whether the buffering of stdout meant that the output to a file would be incomplete if a process is killed. I tried this by printing 8000 chars to stdout with the test app I shared and killing the process from the Windows Task Manager. I found that the characters after the first 4096 were written to the file when the process was killed. This means that it seems that Windows always flushes all output, even when the process is killed. This is different from Wine behavior too.
./wine [[your exec and args]] < /dev/null 2>&1 | cat -
3) The ordering of the output to the terminal appears to be stdout first and stderr second. They are not interleaved as I might have expected. Is it possible to interleave the output depending on the time the print actually happened?
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #7 from Eric Pouech eric.pouech@gmail.com --- (In reply to renatopereyra from comment #5)
Thanks for debugging this, Eric! I'm sorry I took a while to get back to you.
./wine [[your exec and args]] < /dev/null 2>&1 | cat -
This worked locally whenever the app does not have a console.
- Is there a way to get the output to (also) print to the Linux side even
when there is a console?
the command above ensures that: - wine is started without a (unix) console - but first program has its I/O stream bound to the unix fd (here 1,2 of wine program are printed to unix 1) - if first program starts another GUI program, the Windows default behavior is that the streams are *NOT* inherited by second (and subsequent program) - under certain conditions, Wine starts first a dedicated program (start.exe); if you're in that case, your launched app will not be able to print - you can test if its the case by ensuring that you use the full path to your application on command line
2 It seems a bit unsafe to rely on this long-term. Is there or could there be some kind of test in Wine that protects this kind of use/behavior?
what do you mean?
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #8 from Eric Pouech eric.pouech@gmail.com --- (In reply to renatopereyra from comment #6)
I sent my comment too soon. I forgot to mention two more things.
I also tested whether the buffering of stdout meant that the output to a file would be incomplete if a process is killed. I tried this by printing 8000 chars to stdout with the test app I shared and killing the process from the Windows Task Manager. I found that the characters after the first 4096 were written to the file when the process was killed. This means that it seems that Windows always flushes all output, even when the process is killed. This is different from Wine behavior too.
I'll try some tests on this one, but the only way this could happen is if the app is smoothly terminated (ie the msvcrt atexit handlers or equiv are called). I very much doubt that TerminateProcess() will do the same. So this shall be tested with the same way of terminating between Wine and Windows.
./wine [[your exec and args]] < /dev/null 2>&1 | cat -
- The ordering of the output to the terminal appears to be stdout first and stderr second. They are not interleaved as I might have expected. Is it possible to interleave the output depending on the time the print actually happened?
by default (msvcrt), stdout is buffered while stderr isn't. it tested a loop ``` for (int i = 0; i < 1000; i++) { fprintf(stdout, "stdout %i\n", i); fprintf(stderr, "stderr %i\n", i); Sleep(100); } ``` lines from stderr are printed, until stdout buffer is full (its content is printed in bulk), then stderr keeps on printing and so...
so to achieve what you want, you need to: - either unbuffer stdout (that's at application level: setvbuf(stdout, NULL, _IONBF, 0); - or stop printing to both stderr and stdout and use only one them
moreover, what you seem to want is line buffering (ie ensuring a line up to \n is printed at once); this is defined in CRT with _IOLBF flag to setvbuf. Sadly, native Windows CRT implements _IOLBF as _IOFBF, so it won't be of any help here.
https://bugs.winehq.org/show_bug.cgi?id=56459
Ken Sharp imwellcushtymelike@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Keywords| |source
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #9 from renatopereyra@google.com ---
This worked locally whenever the app does not have a console.
- Is there a way to get the output to (also) print to the Linux side even
when there is a console?
the command above ensures that:
- wine is started without a (unix) console
- but first program has its I/O stream bound to the unix fd (here 1,2 of wine program are printed to unix 1)
- if first program starts another GUI program, the Windows default behavior is that the streams are *NOT* inherited by second (and subsequent program)
- under certain conditions, Wine starts first a dedicated program (start.exe); if you're in that case, your launched app will not be able to print
- you can test if its the case by ensuring that you use the full path to your application on command line
Thank you for this context. I found it valuable. However, I think my wording was confusing. Sorry about that. I meant that your suggestion worked except when the Windows app allocated a console via `AllocConsole`. In that case, the output would go to the wineconsole (only). I was wondering if there was a way to send it both to the wineconsole _and_ to the Linux terminal.
2 It seems a bit unsafe to rely on this long-term. Is there or could there be some kind of test in Wine that protects this kind of use/behavior?
what do you mean?
I am not sure if `< /dev/null 2>&1 | cat -` relies on expected Wine behavior that is protected by tests/review/design of some kind or if it simply leverages something that happens to work out _right now_ based on the _current_ implementation of Wine (but could change in the future).
lines from stderr are printed, until stdout buffer is full (its content is printed in bulk), then stderr keeps on printing and so...
This does not match what I observed with the latest Wine 9.5 release using `< /dev/null 2>&1 | cat -`. I found stdout to print first as a whole block, even when the buffer size had not been exceeded. The command line I used was `wine debug_string_test.exe -count 4000 < /dev/null 2>&1 | cat -`, based on the test app I attached to this bug.
moreover, what you seem to want is line buffering (ie ensuring a line up to \n is printed at once); this is defined in CRT with _IOLBF flag to setvbuf. Sadly, native Windows CRT implements _IOLBF as _IOFBF, so it won't be of any help here.
My limited testing in Windows suggests this is applicable when output is routed to a file but not when output is printed to a console allocated by `AllocConsole`. The Windows console appears to be line-buffered. The command line I used was `debug_string_test.exe -count 2 -console_before_print` and I observed stderr interleaved with stdout.
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #10 from Eric Pouech eric.pouech@gmail.com ---
Thank you for this context. I found it valuable. However, I think my wording was confusing. Sorry about that. I meant that your suggestion worked except when the Windows app allocated a console via `AllocConsole`. In that case, the output would go to the wineconsole (only). I was wondering if there was a way to send it both to the wineconsole _and_ to the Linux terminal.
If the app calls explicitely AllocConsole (or implicitely because of new process from CreateProcess), Wine implements windows' behavior which is to create a new windowed console and attach the process to it. AFAIK there's no simple way even on windows to capture current console content (the hacky way would be to send Ctrl-A, Enter keys to console window to copy console content to clipboard).
I am not sure if `< /dev/null 2>&1 | cat -` relies on expected Wine behavior that is protected by tests/review/design of some kind or if it simply leverages something that happens to work out _right now_ based on the _current_ implementation of Wine (but could change in the future).
I don't see that changing in future as it's based on the criterion to create a console attached to a unix terminal (it's done when at least one of fd 0,1,2 is a tty). We could think of "nicer" way of doing it (eg. env variable not to bind to unix console when set, or small shell script to wrap that up...) something like this would do: ``` #!/bin/sh
if [ -t 0 ]; then exec 0< /dev/null ; fi if [ -t 1 ]; then exec 1> /dev/null ; fi if [ -t 2 ]; then exec 2> /dev/null ; fi
exec "$@" ```
This does not match what I observed with the latest Wine 9.5 release using `< /dev/null 2>&1 | cat -`. I found stdout to print first as a whole block, even when the buffer size had not been exceeded. The command line I used was `wine debug_string_test.exe -count 4000 < /dev/null 2>&1 | cat -`, based on the test app I attached to this bug.
the fix for unbuffering stderr will land in Wine 9.7
moreover, what you seem to want is line buffering (ie ensuring a line up to \n is printed at once); this is defined in CRT with _IOLBF flag to setvbuf. Sadly, native Windows CRT implements _IOLBF as _IOFBF, so it won't be of any help here.
My limited testing in Windows suggests this is applicable when output is routed to a file but not when output is printed to a console allocated by `AllocConsole`. The Windows console appears to be line-buffered. The command line I used was `debug_string_test.exe -count 2 -console_before_print` and I observed stderr interleaved with stdout.
console is unbuffered
to check your claim this you need to intertwin write:s to stdout and stderr.
for (int i = 0; i < 2000; i++) { fputc('1', stdout); fputc('2', stderr); if (!(i % 37)) { fputc('\n', stdout); fputc('\n', stderr); } } and you should get: - lines of "12" character pairs when not buffered - pair of a line of 1:s followed by a line of 2:s when line buffered - block (4096 chars) of lines of 1 followed by block of lines of 2 when buffered
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #11 from renatopereyra@google.com ---
We could think of "nicer" way of doing it (eg. env variable not to bind to unix console when set, or small shell script to wrap that up...)
I think an env var would be optimal and even better if the behavior of the env var is tested.
The wrapper script can be a temporary solution.
console is unbuffered
Are you confirming that this is how Windows consoles (and therefore wineconsole) should behave?
to check your claim this you need to intertwin write:s to stdout and stderr.
... Or are you asking me to confirm my observations?
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #12 from Eric Pouech eric.pouech@gmail.com --- (In reply to renatopereyra from comment #11)
We could think of "nicer" way of doing it (eg. env variable not to bind to unix console when set, or small shell script to wrap that up...)
I think an env var would be optimal and even better if the behavior of the env var is tested.
The wrapper script can be a temporary solution.
I'll see what we can push upstream (actually, I think there are already too many env variables for Wine, so I would not favor that one, but let's see maintainers' stance) whatever the solution, it'll be hard to automate the testings as none of the tests are run attached to a unix console, and even less able to generate input or read output to that console (this is doable - if have locally bits of this -, but would require a lot of new stuff upstream, that are likely not to be approved) But if someone wants to create its own testbed, go ahead
console is unbuffered
Are you confirming that this is how Windows consoles (and therefore wineconsole) should behave?
yes
to check your claim this you need to intertwin write:s to stdout and stderr.
... Or are you asking me to confirm my observations?
no, I've done it already. I'm just saying that your program (as you sent it) cannot test that claim.
--- Comment #13 from renatopereyra@google.com ---
I'll see what we can push upstream (actually, I think there are already too many env variables for Wine, so I would not favor that one, but let's see maintainers' stance) whatever the solution, it'll be hard to automate the testings as none of the tests are run attached to a unix console, and even less able to generate input or read output to that console (this is doable - if have locally bits of this -, but would require a lot of new stuff upstream, that are likely not to be approved) But if someone wants to create its own testbed, go ahead
Thanks! I appreciate this. Please let me know what, if anything, can be added upstream.
no, I've done it already. I'm just saying that your program (as you sent it) cannot test that claim.
Ah, yes, I see your point now. Thanks for clarifying.
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #14 from renatopereyra@google.com --- I've been thinking a bit about how Wine creates a (windows) console behind the scenes whenever a program is invoked from a unix tty. Is this done to improve compatibility? If so, would `./wine [[your exec and args]] < /dev/null 2>&1 | cat -` possibly introduce bugs?
Does the answer vary depending on whether the app called is a GUI app or command line app?
https://bugs.winehq.org/show_bug.cgi?id=56459
--- Comment #15 from Eric Pouech eric.pouech@gmail.com --- Any windows program (CUI/GUI) can be attached to a console unless a GUI program explicetly asks for creating a console (AllocConsole()), it has no console (and not inherited by parent) a CUI program inherits its parent console (unless the parent asks not to) the redirection trick from unix command line: - for a GUI program does nothing as it doesn't get console - for a CUI program somehow inherits the "parent console" from the Unix world (that's what we call a unix console, contrary to the one created by AllocConsole()). The redirection trick just forbids that attachment.
From Wine point of view, this doesn't create a "new" state. So there is no hidden risk. OTOH regular console and Unix console are not on par feature wise (and likely never will be).
-
WineHQ Bugzilla