Missing Logs: Inconsistent and Unexpected I/O flush behavior

[renatopereyra]

This is a Proton Wine counterpart of an upstream Wine issue I just filed (summary below) describing how, under some conditions, I observed application prints missing from a Linux terminal and/or I/O redirect. This made my recent debugging of ValveSoftware/Proton#7529 much more challenging because I was working with limited information.

I found the behavior in Proton Experimental (9.0) to be substantially different (worse) from Wine 9.0 and 9.4 so I thought this should merit its own bug report.

In summary:

1. I put together a simple app that prints to stderr and is configurable to cover multiple corner cases.
2. In all cases, I found that there were some number of prints missing when running the app through Proton Experimental.

Full details here. I'm unable to make the drive fully public per my organization's policies so please request access.

[renatopereyra]

Friendly ping. I would appreciate review of this bug since I think it could affect future debugging ability with Proton 9.0.

[ivyl]

I've requested access.

How are your running Proton? Are the lines missing form the log file created with PROTON_LOG=1? Keep in mind the tips on preserving file descriptors that Eric has shared in the upstream bug. What extra logging you get from the application? We usually work with things that use OutputDebugString() - that's a common pattern for logging in anything GUI in the Windows world due to how the handle inheritance works.

I don't think I've ever had issues with OutputDebugString() or Wine's TRACE()s.

Are you using software that you cannot modify that prints out things like that? Is using stdout/stderr necessary? TBH it sounds like a time sink that. may not be worth it if it's just for custom debugging programs when there are better mechanisms.

[renatopereyra]

How are your running Proton?

I've run my test application both through the Steam client as an external "game" and through a Linux terminal with the short script below.

local:~$ cat ./run_proton_exp.sh
#!/bin/bash

export STEAM_COMPAT_DATA_PATH=$HOME/.compatdata
export DXVK_STATE_CACHE_PATH=$STEAM_COMPAT_DATA_PATH
export STEAM_COMPAT_CLIENT_INSTALL_PATH=""
export SteamGameId=0

DISPLAY=:0 $HOME/.steam/steam/steamapps/common/SteamLinuxRuntime_sniper/_v2-entry-point --verb=waitforexitandrun -- $HOME/.steam/steam/steamapps/common/Proton\ -\ Experimental/proton waitforexitandrun $*

Are the lines missing form the log file created with PROTON_LOG=1?

Yes. I modeled my test application to behave the same as the Paradox Launcher in ValveSoftware/Proton#7529 linked above and the game in that case did not have these prints in the proton log. ANGLE, used by the Paradox Launcher, was specifically using an fprintf to stderr, so I used printf to stderr in my test application. (Note from that bug that the mentions of WGL_NV_DX_interop2 shown in intel-steam-stdout-255710.log are missing from intel-steam-255710.log.zip. )

Keep in mind the tips on preserving file descriptors that Eric has shared in the upstream bug.

I applied < /dev/null 2>&1 | cat - to the end of the command line but it did not help like it did for the latest wine release.

Are you using software that you cannot modify that prints out things like that?

I wouldn't have had a way to modify the Paradox Launcher and I wouldn't have a way to modify any other game that might run into this.

Is using stdout/stderr necessary? TBH it sounds like a time sink that. may not be worth it if it's just for custom debugging programs when there are better mechanisms.

Any game that leverages ANGLE at least has the possibility to printf to stderr since that is a pattern that ANGLE follows. There may be other software out there in use by games that may output informational messages in the same way.

[ivyl]

I applied < /dev/null 2>&1 | cat - to the end of the command line but it did not help like it did for the latest wine release.

I've picked up Eric's upstream patches. Can you check with bleeding-edge?

Any game that leverages ANGLE at least has the possibility to printf to stderr since that is a pattern that ANGLE follows. There may be other software out there in use by games that may output informational messages in the same way.

Ah, thanks for the context! FWIW from my experience stdout/err is rarely used by games. Most engines log either to a file directly or use OutputDebugString(). Sounds like it's mostly CEF as used by launchers / nw.js and a few oddballs that use ANGLE directly.

[renatopereyra]

Unfortunately, I didn't find any difference after switching Proton Experimental to the bleeding-edge beta. The trick to unbind unix ttys still did not help. Also, I spot-checked a couple of tests from the spreadsheet I linked in the original bug description and didn't find any differences there either.

[renatopereyra]

Just checking in to see if there is anything I can help unblock in this issue. Please let me know. Thanks!

[ivyl]

Hi. It would be good to have understanding what's different between upstream Wine and Proton that causes the issue for you.

Can you maybe compile standalone wine from our Proton tree and see how that behaves? If you can repro the issue maybe looking at our downstream patches. This would help to get us on the right track.

[renatopereyra]

Is "standalone wine" different from the wine binary produced by the Proton build flow?

[ivyl]

No. I've just meant that you can build Proton's Wine as a standalone and skip proton script to exclude that as a factor.

Few things that are IMO worth checking:

1. does upstream wine-9.0 with the ucrtbase patch helps?
2. if it does, try reverting other patches that affect file descriptors?
3. if that doesn't help maybe a bisect?

If 1. doesn't work it may be that we should backport more patches from upstream to at least be on par with it.