search

ValveSoftware / steam-for-linux

Issue tracking for the Steam for Linux beta client
4.22k stars 174 forks source link

Steamwebhelper Broken (Black Screen) If Stdout/Stderr Not Redirected #8069

Closed TakuyaSama closed 2 years ago

TakuyaSama commented 3 years ago

Your system information

Please describe your issue in as much detail as possible:

I have the Black Screen issue since 10th September, the moment I updated the Steam Client. I updated Steam on my Arch system, the 10th September, it self updated first, then I updated the system, (and I updated freetype2 too, to 2.11.0 finally, after having it frozen because of its issue with previous stable Steam version). I tried what's described on issue #8056, but that didn't fix my issue. I'm having to use the Small Mode since then to launch my only game installed, and I think that's causing an issue, I just noticed I can't open the Steam's properties of that game, so I can't edit the launch options (I have it a little bit modified), cause I wanted to add the gamemode option. I think that using the Small Mode is causing an issue with Telegram Desktop when I'm on a Voice Chat with a mate, we play together, and sometimes on Warframe, when I realize some kind of connection in-game, the mic stops working, and I have to mute and unmute to have it working again and that issue just started since the inability of having Steam launched on the normal mode.

Steps for reproducing this issue:

  1. Launching Steam.
  2. See the black screen instead of the normal loaded homepage, with the news.
kisak-valve commented 3 years ago

Hello @TakuyaSama, if you completely close Steam, then run steam-runtime from a terminal, does the terminal spew give any hints? Also, please copy ~/.local/share/Steam/logs/steamwebhelper.log to a gist and share a link or attach the log as a file.

VoidedWinter commented 3 years ago

Can verify this is not limited to Arch, have on ubuntu 20.04 LTS.

mittorn commented 3 years ago

/home/mittorn/.local/share/Steam/ubuntu12_64/steam-runtime-heavy.sh: строка 55: STEAM_ZENITY: не заданы границы переменной

kisak-valve commented 3 years ago

Hello @mittorn, that sounds like https://github.com/ValveSoftware/steam-runtime/issues/458. Can you check if your system has zenity installed? If not, then please check if installing it works around that issue for you.

mittorn commented 3 years ago

I faked STEAM_ZENITY in steam-runtime-heavy.sh and it works, but script is rewriten at every launch. I have no gtk+ in my system to install zenity, and it worked without it before

mittorn commented 3 years ago

Also having zenity alternatives or some scripts instead of zenity does not help, it just not called because of error in script (STEAM_ZENITY always empty)

mittorn commented 3 years ago

installing zenity changes nothing (because it's only script error) please fix zenity detect in steam runtime script, it's just broken not depending if it installed or not (steam-runtime-heavy.sh file)

mittorn commented 3 years ago

this was because SYSTEM_ZENITY was unset. Maybe arch uses some modified steam.sh too? updated my steam launch script and it works now

TakuyaSama commented 3 years ago

Hello @TakuyaSama, if you completely close Steam, then run steam-runtime from a terminal, does the terminal spew give any hints? Also, please copy ~/.local/share/Steam/logs/steamwebhelper.log to a gist and share a link or attach the log as a file.

Hmmmm, strange, launching Steam using steam-runtime via terminal launched everything fine, all loaded as expected. steamwebhelper.log

mittorn commented 3 years ago

How steam is launching normally in your distro? Can you examine steam desktop file and script which i points to?

TakuyaSama commented 3 years ago

How steam is launching normally in your distro? Can you examine steam desktop file and script which i points to?

I launch it via a Shortcut, using Meta + G, to launch Steam. As I said, it launches with the black screen. Where can I find the desktop file to edit? My desktop is empty of folders/icons. Thanks in advance.

kisak-valve commented 3 years ago

Hello, the 2021-09-13 Steam client update has some updates related to the initialization of Steam's web component. Please retest this issue.

That said, since you can't reproduce the issue with steam-runtime, that hints that you have steam-native-runtime installed on your system, and your issue is related to steam-native or a distro-specific package modification by Arch's package maintainer(s) for Steam, which starts Steam with the Steam runtime disabled. That configuration is unsupported and any issues with steam-native must be resolved by you or the package maintainers that helped disable the Steam runtime.

TakuyaSama commented 3 years ago

Hello, the 2021-09-13 Steam client update has some updates related to the initialization of Steam's web component. Please retest this issue.

That said, since you can't reproduce the issue with steam-runtime, that hints that you have steam-native-runtime installed on your system, and your issue is related to steam-native or a distro-specific package modification by Arch's package maintainer(s) for Steam, which starts Steam with the Steam runtime disabled. That configuration is unsupported and any issues with steam-native must be resolved by you or the package maintainers that helped disable the Steam runtime.

I see, I just received the update when launching Steam a few minutes ago and it's still the same, so I should report it to the Arch's maintainers. OK, thanks for the information :).

VoidedWinter commented 3 years ago

Latest update has corrected the issue for me.

theaprilhare commented 3 years ago

I'm having what appears to be the same issue as @TakuyaSama -- a black screen when I open Steam from the Desktop file, but not when I open it from the command line.

Your system information

Oddly, the steam.desktop executes /usr/bin/steam-runtime, which is exactly what seems to work when I try running from the command line.

Here's Help -> System Information when run from the desktop file, and the corresponding information when run from the command line. ~/.local/share/Steam/logs/steamwebhelper.log isn't written when launched from the desktop file, but here it is when launched from the command line. Here is the terminal output when running /usr/bin/steam-runtime from the terminal.

To address a couple of potential issues raised above, I have steam-runtime and not steam-native installed, and zenity is also installed.

kisak-valve commented 3 years ago

Hello @theaprilhare, there's not many things that would differ between running Steam from a desktop shortcut and from the terminal. It might be interesting for you to compare the environment variables Steam has when it's behaving compared to when libcef fails to initialize. One relatively easy way to do that is to install and run htop, then navigate to the Steam process and press e to show that process's environment variables, then slowly add the differences to running Steam from a terminal until libcef misbehaves.

Looking at your system information, it looks like you have a single gpu system, but DRI_PRIME=1 is getting set, which is curious since that's usually how you select the second logical GPU of a system with mesa. Since the Steam 1.0.0.70 package, PrefersNonDefaultGPU=true was added to the desktop shortcut (https://github.com/ValveSoftware/steam-for-linux/issues/7089#issuecomment-814928384) to help with the out of the box behavior of Optimus laptops. If your desktop environment supports that .desktop setting, then it should apply some logic to figure out how to make that work based on your hardware, which would be DRI_PRIME=1 for mesa-based drivers.

I'd expect if that was causing the problem on your system, it would either work fine, or cause Steam to completely fail to use OpenGL, not limited to causing libcef trouble. That said, it might be interesting to test how running Steam with DRI_PRIME=1 steam-runtime from a terminal behaves. The other side of the riddle would be to test if changing steam.desktop to have PrefersNonDefaultGPU=false influences the client's behavior.

theaprilhare commented 3 years ago

Thanks for the suggestions, @kisak-valve. I ran a diff between the environmental variables when launched from the command line vs. the desktop file, but there were few differences, none of which seemed like it would be causing the issue. Trying to tweak the environmental variables for the desktop file version to be more like the command line version also didn't seem to fix things.

As you noted, DRI_PRIME=1 was getting set when run from the desktop file, but that doesn't seem to be the issue -- that environmental variable disappears (as expected) when steam.desktop is changed to have PrefersNonDefaultGPU=false (as you suggested), but the black screen persists. (And similarly, running DRI_PRIME=1 steam-runtime from the terminal works properly.) It's all very puzzling!

theaprilhare commented 3 years ago

I modified /usr/bin/steam-runtime to add the second line to track what was going wrong:

#!/bin/sh
exec > /home/raghav/steam.log 2>&1
exec /usr/lib/steam/steam "$@"

And all of a sudden, launching Steam from the desktop file works. In fact, redirecting stdout anywhere in the second line seems to work. Remove the second line, and the Steam windows are again black.

No idea why why it works, but it does.

TakuyaSama commented 3 years ago

I modified /usr/bin/steam-runtime to add the second line to track what was going wrong:

#!/bin/sh
exec > /home/raghav/steam.log 2>&1
exec /usr/lib/steam/steam "$@"

And all of a sudden, launching Steam from the desktop file works. In fact, redirecting stdout anywhere in the second line seems to work. Remove the second line, and the Steam windows are again black.

No idea why why it works, but it does.

I took the freedom of copy your "fix" to check if it solved the issue on my system, and, in fact, it fixed it too :).

Thank you very much.

This should have us covered until Valve fixes the issue properly, when they discover what's causing it. I was rather annoyed to having to launch Steam Runtime from Krunner instead of using my keyboard shortcut :(.

Thank you very much for the help and for sharing with us your issue too and workaround, even though we don't know why this "fix" solved it XD.

Hope it gets fixed by Valve soon.

Technohacker commented 3 years ago

I'm assuming this is the same issue I'm facing, and yes with the Flatpak version of Steam, launching it from the terminal using flatpak run com.valvesoftware.Steam (where stdout is shown on terminal) makes the Steam client work again

smcv commented 3 years ago

The "black screen issue" is a symptom, not a bug: it can be caused by anything that breaks the steamwebhelper. Different people can experience this symptom for different reasons. If we try to treat multiple root causes as the same bug, we'll just spend a lot of time getting confused, which is time we cannot spend fixing bugs; so please help us to keep things separate!

It sounds as though we have more than one root cause here:

The original reporter of this issue is @TakuyaSama, so we will continue to investigate that bug here, and anyone who is getting the same symptom for a different reason should open a separate issue.

@mittorn, if you get this symptom for a different reason, or if you believe Steam is doing something wrong involving SYSTEM_ZENITY, please open a separate issue with full details.

Technohacker commented 3 years ago

My bad, forgot to mention the distro: Fedora Silverblue (Kinoite) F35. Steam Flatpak version from Flathub stable

EDIT: Now that I look at my previous message, I can see how that doesn't help matters :sweat_smile: The symptom I experience is the main window (and promotional popup window) content not rendering anything and showing black. This occurs in any page of the window. The native shell itself does render fine and I can interact with it

smcv commented 3 years ago

@TakuyaSama or @kisak-valve, please could you retitle this to something like "steamwebhelper broken (black screen) if stdout/stderr not redirected", to encourage other people with the same symptom for different reasons to open a separate issue?

smcv commented 3 years ago

@TakuyaSama, do I assume correctly from your Github avatar that you are using KDE to launch Steam?

@theaprilhare, you mentioned Krunner. Does this mean you are also using KDE?

@Technohacker, you mentioned Fedora Silverblue (Kinoite), which seems to be a KDE variant of Silverblue, similar to the relationship between Kubuntu and Ubuntu. Is that true?

This makes me suspect that the common factor might be that you are launching Steam from a KDE desktop environment, either from the desktop environment's menus or from a keyboard shortcut that is equivalent to launching it from the menus.

Technohacker commented 3 years ago

Yep, that's right. Kinoite is a KDE spin of Silverblue. And yes, when I launch from the app menu, it breaks with those symptoms. Launch from terminal using flatpak run made it work

TakuyaSama commented 3 years ago

@TakuyaSama, do I assume correctly from your Github avatar that you are using KDE to launch Steam?

That's it, Plasma 5.23 Beta, but the issue started before I updated to the Plasma beta. I have configured mostly the software I use the most with Plasma's Shorcuts, so I can keep my desktop clean, as I always have.

This makes me suspect that the common factor might be that you are launching Steam from a KDE desktop environment, either from the desktop environment's menus or from a keyboard shortcut that is equivalent to launching it from the menus.

You could be right, yeah. So you're proposing the issue could come from any part of Plasma? But if that's the case, why haven't I been experiencing it before I started to report it here on this Steam for Linux's repo issues?

smcv commented 3 years ago

Some things for any/all of you to try, that would give us more information:

If you are not already using the Steam client beta, it would also be useful information if you could try again with the beta.

For example, I'm trying to reproduce this on an Arch Linux system with KDE Plasma Desktop in Wayland mode.

Finding the highest-level Steam process: I used systemd-cgls to list processes. They include:

│   │ │ ├─app-steam-0068eb40ee194714ba4dd1e0a5835fcf.scope 
│   │ │ │ ├─1597 bash /home/desktop/.steam/debian-installation/steam.sh
│   │ │ │ ├─1727 /home/desktop/.steam/debian-installation/ubuntu12_32/steam
│   │ │ │ ├─1770 /home/desktop/.steam/debian-installation/ubuntu12_32/steam

(This is an Arch system, but the home directory on this test machine is shared with lots of other OSs, and my Steam installation was originally on Debian for historical reasons.)

Steam messages in the log file: I'm not going to quote all of them because it isn't useful (I cannot reproduce this bug) but the first few are:

Installing breakpad exception handler for appid(steam)/version(1632409172)
Installing breakpad exception handler for appid(steam)/version(1632409172)
Loaded SDL version 2.0.17-6744061
smcv commented 3 years ago

So you're proposing the issue could come from any part of Plasma?

It could be caused by Plasma doing something wrong, or it could be caused by Plasma doing something that is correct but causes Steam to go wrong by breaking its assumptions. We don't know yet!

But if that's the case, why haven't I been experiencing it before I started to report it here on this Steam for Linux's repo issues?

This could have been triggered by a change in Plasma, or a change in Steam, or a change in lower-level parts of your OS.

theaprilhare commented 3 years ago

@theaprilhare, you mentioned Krunner. Does this mean you are also using KDE?

I think it was @TakuyaSama who mentioned Krunner; I'm not using KDE and use wofi as my launcher.

smcv commented 3 years ago

OK, that makes it less likely that this is KDE-specific.

There must be something connecting your system configurations: I would normally expect redirecting output to a log file to have no practical effect, other than where the messages end up.

The fact that redirecting output works around this reminded me of https://bugs.freedesktop.org/show_bug.cgi?id=97008, which was caused by lightdm accidentally running programs with their stdin/stdout/stderr closed (which is not really meant to happen). The root cause for that was fixed in lightdm long ago, but maybe you are experiencing something vaguely similar?

smcv commented 3 years ago

Another possibility is that you might have a PS4 environment variable that contains variable expansions like ${foo}, while not running the Steam beta. If that's the case, then that's #8093, which is fixed in the beta - but I would not have expected redirecting stdout/stderr to be a workaround for that.

Technohacker commented 3 years ago

Alright writing down my observations here now

  1. My workarounds were merely the flatpak run command. No modification to launchers

  2. Plasma System Information Output

    Operating System: Fedora Linux 35
KDE Plasma Version: 5.22.4
KDE Frameworks Version: 5.85.0
Qt Version: 5.15.2
Kernel Version: 5.14.0-60.fc35.x86_64 (64-bit)
Graphics Platform: Wayland

    Additional information from Flatpak

    Steam - Manage and play games distributed by Steam

      ID: com.valvesoftware.Steam
     Ref: app/com.valvesoftware.Steam/x86_64/stable
    Arch: x86_64
  Branch: stable
 Version: 1.0.0.71
 License: LicenseRef-proprietary
  Origin: flathub
Collection: org.flathub.Stable
Installation: system
Installed: 41.1 MB
 Runtime: org.freedesktop.Platform/x86_64/21.08
     Sdk: org.freedesktop.Sdk/x86_64/21.08

  Commit: d8fc06b6048776fcd7de4fac9848cc5a84289abeb8e589e731e0e0f05fb56493
  Parent: b5bc849bc8e5b8ac924a2538a71b342b929d7ca3f1d53e2f2de57e6dea9753ea
 Subject: Revert "Attempt to fix Steam desktop symlinks" (f9812b6b)
    Date: 2021-09-12 16:34:33 +0000
  3. Launching steam from the Terminal using flatpak run com.valvesoftware.Steam does make the content render correctly (no black screen)
  4. Clicking on Application launcher menu > Search for Steam > Only one application result shows up. Desktop file is /var/lib/flatpak/app/com.valvesoftware.Steam/current/active/export/share/applications/com.valvesoftware.Steam.desktop Desktop file command is /usr/bin/flatpak run --branch=stable --arch=x86_64 --command=/app/bin/steam-wrapper --file-forwarding com.valvesoftware.Steam @@u %U @@ Trying to launch this way will result in black screen over content section of the window
  5. Steam version information 
    Built: Sep 17 2021, at 04:30:38
Steam API: v020
Steam package versions: 1631912732
  6. Process information: 
    $ ps aux | grep steam
technoh+  153257  0.0  0.0   7924  4148 ?        S    21:17   0:00 bash /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/steam.sh
# ...
$ ls -l /proc/153257/fd
lr-x------. 1 technohacker technohacker 64 Sep 24 21:22 0 -> 'pipe:[1047583]'
lrwx------. 1 technohacker technohacker 64 Sep 24 21:22 1 -> 'socket:[16376]'
# ...
lrwx------. 1 technohacker technohacker 64 Sep 24 21:22 2 -> 'socket:[16376]'
  7. journalctl only has these lines for Steam 
    Sep 24 21:17:45 fedora systemd[2905]: Started Steam.
Sep 24 21:17:46 fedora systemd[2905]: Started app-flatpak-com.valvesoftware.Steam-153242.scope.
  8. Files do not point to log files, only sockets EDIT: Checked journalctl on user for the systemd scope: 
    $ journalctl --user -u app-flatpak-com.valvesoftware.Steam-153242.scope
-- Journal begins at Fri 2021-08-06 19:30:54 IST, ends at Fri 2021-09-24 21:24:19 IST. --
Sep 24 21:17:46 fedora systemd[2905]: Started app-flatpak-com.valvesoftware.Steam-153242.scope.
Sep 24 21:17:47 fedora steam[153400]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Sep 24 21:17:48 fedora steam[153400]: gtk_disable_setlocale() must be called before gtk_init()
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 21:17:51 fedora steam[153400]: Trying to remove a child that doesn't believe we're it's parent.

I initially identified this bug in the beta, and switched to stable to check if it wasn't just a beta-only bug

Contents of $PS4: +%N:%i>

smcv commented 3 years ago 
lrwx------. 1 technohacker technohacker 64 Sep 24 21:22 1 -> 'socket:[16376]'
# ...
lrwx------. 1 technohacker technohacker 64 Sep 24 21:22 2 -> 'socket:[16376]'

I'm guessing that's the systemd journal on stdout and stderr, since you're getting Steam output in the journal. That's an entirely reasonable thing for a desktop environment to connect to an app's stdout and stderr.

lr-x------. 1 technohacker technohacker 64 Sep 24 21:22 0 -> 'pipe:[1047583]'

This seems odd: I would have expected stdin to be /dev/null rather than a pipe. This makes me wonder whether steamwebhelper or steamwebhelper.sh is reading from stdin somewhere, which would make it block?

Is there anything further back in the Journal above the part you quoted? Steam should log Loaded SDL version 2.0.17-something soon after it starts.

Contents of $PS4: +%N:%i>

OK, so at least @Technohacker (and probably the others) is not experiencing #8093.

Technohacker commented 3 years ago

I tried journalctl --user | grep "Loaded SDL version" and last mention of that line was:

Sep 21 19:59:35 fedora plasmashell[25627]: Loaded SDL version 2.0.17-6744061

This was 3 days ago

Time in IST. This is the output from the last successful run

Sep 21 19:59:32 fedora systemd[2847]: Started app-flatpak-com.valvesoftware.Steam-25466.scope.
Sep 21 19:59:32 fedora plasmashell[25479]: INFO:root:https://github.com/flathub/com.valvesoftware.Steam/wiki
Sep 21 19:59:32 fedora plasmashell[25479]: INFO:root:Will set XDG dirs prefix to /var/home/technohacker/.var/app/com.valvesoftware.Steam
Sep 21 19:59:32 fedora plasmashell[25479]: INFO:root:Overriding TZ to Asia/Kolkata
Sep 21 19:59:32 fedora plasmashell[25479]: Running Steam on org.freedesktop.platform 21.08.2 64-bit
Sep 21 19:59:32 fedora plasmashell[25479]: STEAM_RUNTIME is enabled automatically
Sep 21 19:59:32 fedora plasmashell[25554]: Steam runtime environment up-to-date!
Sep 21 19:59:34 fedora plasmashell[25479]: Steam client's requirements are satisfied
Sep 21 19:59:34 fedora plasmashell[25479]: WARNING: Using default/fallback debugger launch
Sep 21 19:59:34 fedora plasmashell[25479]: /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_32/steam
Sep 21 19:59:34 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:34 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Loaded SDL version 2.0.17-6744061
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25681]: Runtime for steamwebhelper: defaulting to /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_64/steam-runtime-heavy
Sep 21 19:59:35 fedora plasmashell[25681]: + exec /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_64/steam-runtime-heavy.sh --unpack-dir=/var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_64 --runtime=steam-runtime-heavy -- ./steamwebhelper -lang=en_US -cachedir=/var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/config/htmlcache -steampid=148 -buildid=1631753195 -steamid=0 -cachedir=/var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/config/htmlcache -steamuniverse=Public -realm=Global -clientui=/var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/clientui --enable-blink-features=ResizeObserver,Worklet,AudioWorklet --enable-media-stream --enable-smooth-scrolling --password-store=basic --log-file=/var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/logs/cef_log.txt --disable-quick-menu
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: CAppInfoCacheReadFromDiskThread took 101 milliseconds to initialize
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Warning: failed to set thread priority: set failed for 8: -1: setpriority() failed
Sep 21 19:59:35 fedora plasmashell[25627]: Warning: failed to set thread priority: set failed for priority 8
Sep 21 19:59:35 fedora plasmashell[25627]: Warning: support for elevated priorities is most likely unavailable, suppressing future warnings
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Warning: failed to set thread priority: set failed for 8: -1: setpriority() failed
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:35 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora steam[25627]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Installing breakpad exception handler for appid(steam)/version(1631753195)
Sep 21 19:59:36 fedora plasmashell[25627]: Proceed to auto login

I do have to note though, that my install had to be downgraded from Rawhide to 35, and in the process, I do remember the version number dropping by one minor version for Plasma and KDE Frameworks. I'm trying to find the downgrade information, but off the top of my head, it was from 5.23 to 5.22, and 5.86 to 5.85 IIRC

smcv commented 3 years ago

Hmm. Now I'm not so sure that your newer logging is really going to the Journal...

It might be useful to look at the output of ss -p and look for references to the socket inode number (that's the 16376 in socket:[16376]'). If it's really the systemd journal, you'd see something like this (where my 7867108 is the equivalent of your 16376, and I'm using seahorse as a stand-in for Steam to get an example of a program that is definitely writing stderr to the journal):

u_str ESTAB      0      0  /run/systemd/journal/stdout 7867109 * 7867108
...
u_str ESTAB      0      0                            * 7867108 * 7867109  users:(("seahorse",pid=1257353,fd=2))

my install had to be downgraded from Rawhide to 35

I don't know whether the "library pinning" mechanism is 100% compatible with downgrades. It might be interesting to:

If that resolves this for you, then we should probably discuss that on a separate issue report, because it is probably not the same root cause as the original report here.

theaprilhare commented 3 years ago

Here's the requested information from me, using the beta.

Some things for any/all of you to try, that would give us more information:

. . .

  • What versions of major KDE components are you using?

None.

  • Run a terminal (Konsole, xterm, gnome-terminal or similar), and run steam from that. Does it work correctly like that? From what @Technohacker said, I suspect it does. However, if it does not, then that's really useful information: please copy its output and send it as a gist or attachment. Whether it works or not, exit from Steam completely before continuing.

Yep.

  • Launch Steam in whatever way does not work, and say what you did.

I launched wofi (Meta+D) and selected "Steam (Runtime)".

  • Use Help -> About Steam to tell us the Steam version, since you might have received an upgrade since the initial report, and it'll be easier to deal with this if we know which versions are and are not affected.

1632409172, built Sep 23, 2021.

  • With Steam still running and the steamwebhelper still not working, find the process ID of a steam.sh or steam process - preferably the "highest-level" Steam process in the process tree, which will probably be steam.sh. If the process ID is 12345, look at ls -l /proc/12345/fd to see what files the steam process has open. The file descriptors I am particularly interested in are 0, 1 and 2.
lr-x------ 1 raghav raghav 64 Sep 24 09:37 0 -> /dev/null
l-wx------ 1 raghav raghav 64 Sep 24 09:37 1 -> 'pipe:[616071]'
lrwx------ 1 raghav raghav 64 Sep 24 09:37 2 -> /dev/tty1

Full output in this gist.

Note that when I run it from the terminal, the file descriptors are as follows:

lrwx------ 1 raghav raghav 64 Sep 24 09:50 0 -> /dev/pts/1
lrwx------ 1 raghav raghav 64 Sep 24 09:50 1 -> /dev/pts/1
lrwx------ 1 raghav raghav 64 Sep 24 09:50 2 -> /dev/pts/1
  • If you are using systemd, look in the systemd journal to see whether messages from Steam have been logged.

I didn't see anything from Steam in the systemd journal, and I also didn't see a wayland-session.log in ~/.local/share/Steam/logs/.

Contents of $PS4 is simply +.

Technohacker commented 3 years ago 
$ mv /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_32/steam-runtime{,.issue8069}
$ mv /var/home/technohacker/.var/app/com.valvesoftware.Steam/.local/share/Steam/ubuntu12_64/steam-runtime-heavy{,.issue8069}

Launch from App Menu. Symptom is still present.

As for the socket command, I noticed something interesting. Only one record of it. However, it seems to have more than just Steam on it (reran Steam, socket number was still the same: 16376)

u_str              ESTAB                   0                   0                                                                                   * 16376                                                    * 0
users:(("steam",pid=157781,fd=2),("steam",pid=157781,fd=1),("bash",pid=157488,fd=2),("bash",pid=157488,fd=1),("bwrap",pid=157485,fd=2),("bwrap",pid=157485,fd=1),("xdg-dbus-proxy",pid=157483,fd=2) #...

This second line right after the one with the socket number had more than just Steam and bash. It also had processes from my running instance of Firefox, Thunderbird, and LibreOffice, along with Konsole and Plasmashell.

smcv commented 3 years ago

@theaprilhare:

l-wx------ 1 raghav raghav 64 Sep 24 09:37 1 -> 'pipe:[616071]'

This means Steam's stdout is being written to a pipe. I cannot say what is at the other end of that pipe. Is this normal for applications launched by wofi?

How was your environment (Wayland compositor?) started?

How was wofi started?

lrwx------ 1 raghav raghav 64 Sep 24 09:37 2 -> /dev/tty1

This means Steam's stderr is ending up on the virtual console /dev/tty1. If you switch to that virtual console with Ctrl+Alt+F1, you might see some useful debug messages that help to figure out what is going on here?

I would have expected that when Steam (or any other GUI program) is launched by a GUI environment, the GUI environment should be responsible for sending its stdout and stderr to the system journal (if you are using systemd), or to a log file, or as a worst-case scenario, /dev/null. Having stdout written to a pipe and stderr written to a virtual console seems odd to me, and it would not surprise me if this could break something, for example some program writing too much output to stdout and filling up the pipe buffer.

smcv commented 3 years ago

@Technohacker:

As for the socket command, I noticed something interesting. Only one record of it. However, it seems to have more than just Steam on it (reran Steam, socket number was still the same: 16376)

u_str              ESTAB                   0                   0                                                                                   * 16376                                                    * 0
users:(("steam",pid=157781,fd=2),("steam",pid=157781,fd=1),("bash",pid=157488,fd=2),("bash",pid=157488,fd=1),("bwrap",pid=157485,fd=2),("bwrap",pid=157485,fd=1),("xdg-dbus-proxy",pid=157483,fd=2) #...

This means that some parent process (probably plasmashell?) has opened a socket that it is using as stdout and stderr (fds 1 and 2), and then it is letting all its child processes, including Steam and Firefox, inherit that same socket. That would explain why, in your older log, plasmashell[25627] is being "blamed" for the majority of Steam's output - the Journal cannot tell the difference between plasmashell and Steam (although it can tell what the process ID is, in this case 25627).

GNOME Shell used to have the same behaviour, but was improved in 2013 to try to connect each application to a separate Journal stream (although it still doesn't do that for desktop actions). It would probably be useful for Plasma to do the same thing, for the same reasons.

The reason why you see some messages correctly attributed to steam[25627] is that recent versions of GLib (which is used by Steam) detect whether their stdout/stderr are the systemd Journal, and if so, open a new Journal connection so that their log messages can be correctly attributed. However, they only use that connection for messages that go through GLib's structured logging API, not for messages on stdout/stderr from other parts of Steam.

smcv commented 3 years ago

@Technohacker, if you exit from Steam completely, then run journalctl -f to "follow" the end of the journal, and then launch Steam, do you get anything logged?

If not, what if you do the same thing as root: sudo journalctl -f?

Technohacker commented 3 years ago

I am indeed following the journal when I check for those messages the only output lines are from systemd launching, and steam's Glib output. Steam's own messages are here:

Sep 24 22:54:56 fedora systemd[2905]: Started Steam.
Sep 24 22:54:56 fedora systemd[2905]: Started app-flatpak-com.valvesoftware.Steam-163533.scope.
# ...
Sep 24 22:55:01 fedora steam[163683]: gtk_disable_setlocale() must be called before gtk_init()
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.
Sep 24 22:55:03 fedora steam[163683]: Trying to remove a child that doesn't believe we're it's parent.

In between there were more lines from plasmashell and other KDE apps (kded5, plasmashell, kdeconnectd, kgpg). Probably unrelated, but it's this line repeated

Sep 24 22:55:01 fedora kded5[3039]: "Object does not exist at path “/org/freedesktop/NetworkManager/ActiveConnection/1”"

sudo journalctl -f and journalctl --user -f also give the same. I believe Fedora puts the user into the wheel group automatically.

theaprilhare commented 3 years ago

@smcv

This means Steam's stdout is being written to a pipe. I cannot say what is at the other end of that pipe. Is this normal for applications launched by wofi?

It seems to be -- I tried a few and stdout seemed to be directed to a pipe on all but one (Zoom, where it was directed to an application-specific logfile).

How was your environment (Wayland compositor?) started?

It was launched from tty1, through a script that sets a few environment variables and then runs /usr/bin/sway.

How was wofi started?

Through the following lines in ~/.config/sway/config:

set $menu dmenu_path | wofi --show drun -i | xargs swaymsg exec --¬
bindsym $mod+d exec $menu

And then using Mod+d.

lrwx------ 1 raghav raghav 64 Sep 24 09:37 2 -> /dev/tty1

This means Steam's stderr is ending up on the virtual console /dev/tty1. If you switch to that virtual console with Ctrl+Alt+F1, you might see some useful debug messages that help to figure out what is going on here?

Since my Wayland compositor's running on that virtual console it wasn't easy to switch, but when I quit sway I didn't see anything from Steam.

On some further poking around, it seems redirecting stdout is sufficient to fix the issue; redirecting stderr is neither necessary nor sufficient.

smcv commented 3 years ago

On some further poking around, it seems redirecting stdout is sufficient to fix the issue; redirecting stderr is neither necessary nor sufficient.

OK! So in at least @theaprilhare's version of this issue (and maybe others), the root cause is something to do with the pipe used by wofi for apps' stdout.

I'll be interested to see what @TakuyaSama says about the file descriptors. We might have one root cause here, or equally we might have a separate root cause for each of the three of you...

edward-shen commented 3 years ago

@smcv

the root cause is something to do with the pipe used by wofi for apps' stdout.

I ran into this problem as well with a different wayland launcher (kickoff), and looks like I'm able to reproduce and fix it just by redirecting stdout, so it looks like your suspicion is confirmed.

Before adding exec > /dev/null: 

lr-x------ edward edward 64 B Sun Sep 26 00:57:11 2021  0 ⇒ pipe:[60027]
l-wx------ edward edward 64 B Sun Sep 26 00:57:11 2021  1 ⇒ pipe:[60028]
lrwx------ edward edward 64 B Sun Sep 26 00:57:11 2021  2 ⇒ /dev/tty1
lr-x------ edward edward 64 B Sun Sep 26 00:57:11 2021  255 ⇒ /home/edward/.local/share/Steam/steam.sh

steamwebhelper fails to run.

With stdout redirection to /dev/null:

lr-x------ edward edward 64 B Sun Sep 26 00:58:32 2021  0 ⇒ pipe:[79077]
l-wx------ edward edward 64 B Sun Sep 26 00:58:32 2021  1 ⇒ /dev/null
lrwx------ edward edward 64 B Sun Sep 26 00:58:32 2021  2 ⇒ /dev/tty1
lr-x------ edward edward 64 B Sun Sep 26 00:58:32 2021  255 ⇒ /home/edward/.local/share/Steam/steam.sh

steamwebhelper successfully runs.

I assume this requires a fix from the application launchers then?

smcv commented 3 years ago

I assume this requires a fix from the application launchers then?

I don't know yet. It might need a fix in the application launcher, or in whatever component ran the application launcher. If any of you can find out what your chosen application launcher is using this pipe for (what program has the read end of the pipe, and how it behaves), that would probably help us to work out what is happening here.

Unfortunately I wasn't able to reproduce this symptom using KDE Plasma.

@theaprilhare, how are you starting wofi? How can I reproduce something close enough to your environment to see this bug myself?

@edward-shen, same question, but for kickoff?

If there is no program at the read end of the pipe, then that's definitely wrong: anything writing more than a few K to the pipe will block waiting for more buffer space, with the same practical result as if it had deadlocked or otherwise frozen.

It might be possible for a Valve developer to work around this by adding exec >&2 near the beginning of one of the scripts that launches Steam or steamwebhelper, so that all diagnostic messages from Steam or steamwebhelper come out on stderr, ignoring its original stdout. I'm not them (I help to maintain the Steam Runtime, not Steam itself), but if I was in their position, I'd want to understand why I was making that change before making it.

When an application launcher like wofi or kickoff runs an arbitrary application like Steam, it should give the application its standard file descriptors 1 and 2 (stdout and stderr) pointed to somewhere reasonable for the application to write arbitrary human-readable diagnostic (debug/warning) messages. This might be the systemd Journal, or it might be a log file, or it might be a file descriptor inherited from the application launcher's parent, or if there is really nowhere better available, /dev/null is always safe (diagnostic messages will be lost, but at least the application won't block).

Similarly, when the application launcher is run by whatever component runs it in your configuration, that component should give the application launcher its standard file descriptors 1 and 2 (stdout and stderr) pointed to somewhere reasonable for the application to write arbitrary human-readable diagnostic messages - unless there is a defined protocol between the application launcher and the component that runs it, where stdout is used for some special purpose like an "I am ready" notification to its caller.

If the application launcher is using its stdout for some special purpose, like an "I am ready" notification to its caller, then it should give the application some different file descriptor that is suitable for arbitrary human-readable logging (perhaps a copy of the application launcher's stderr) as its stdout, instead of letting the application inherit the application launcher's stdout.

If the application launcher runs applications with stdout closed (like lightdm did in https://bugs.freedesktop.org/show_bug.cgi?id=97008), or if the application launcher gets run with its stdout closed, then that's definitely a bug: in that situation, the first file descriptor that is opened for any purpose will become stdout, which will usually break things.

theaprilhare commented 3 years ago

@theaprilhare, how are you starting wofi? How can I reproduce something close enough to your environment to see this bug myself?

Through sway, with the following lines in ~/.config/sway/config:

set $menu dmenu_path | wofi --show drun -i | xargs swaymsg exec --¬
bindsym $mod+d exec $menu

And then using Mod+d.

edward-shen commented 3 years ago

Thanks for the explanation! I learned something new today. :)

same question, but for kickoff?

Same as @theaprilhare, replacing wofi --show drun -i with just kickoff:

set $menu dmenu_path | kickoff | xargs swaymsg exec --
theaprilhare commented 3 years ago

I don't know yet. It might need a fix in the application launcher, or in whatever component ran the application launcher. If any of you can find out what your chosen application launcher is using this pipe for (what program has the read end of the pipe, and how it behaves), that would probably help us to work out what is happening here.

Not sure if it helps, but I checked to see what process had a matching ID using (find /proc -type l | xargs ls -l | fgrep 'pipe:[<ID>]') 2>/dev/null, and it looks like bash is also writing to that pipe. Not sure what's on the other end.

$ ps -A|grep steam
44401 ?        00:00:03 steam
$ ls -l /proc/44401/fd
total 0
lr-x------ 1 raghav raghav 64 Sep 26 15:02 0 -> /dev/null
l-wx------ 1 raghav raghav 64 Sep 26 15:02 1 -> 'pipe:[272567]'
[snip]
$ (find /proc -type l | xargs ls -l | fgrep 'pipe:[272567]') 2>/dev/null
l-wx------ 1 raghav raghav 64 Sep 26 15:01 /proc/44263/fd/1 -> pipe:[272567]
l-wx------ 1 raghav raghav 64 Sep 26 15:03 /proc/44263/task/44263/fd/1 -> pipe:[272567]
[snip]
l-wx------ 1 raghav raghav 64 Sep 26 15:02 /proc/44401/fd/1 -> pipe:[272567]
[snip]
$ ps -A|grep 44263
44263 ?        00:00:00 bash
smcv commented 3 years ago

it looks like bash is also writing to that pipe. Not sure what's on the other end

If those are the only results (bash and Steam have the write end of the pipe as their stdout), then I think the problem might be that nothing is on the other (read) end, resulting in the failure mode I described in an earlier comment: when Steam writes to stdout, after the pipe's buffer in the kernel fills up, subsequent writes block forever.

If that's the case, then I think this would indeed be an application launcher bug - although it looks as though the application launcher might actually be sway rather than wofi/kickoff, because swaymsg exec just asks sway to start an application via IPC, rather than starting the application itself. Or, if sway is just letting applications inherit its stdout, then this could be a problem with how you start sway (whatever that is).

bash process 44263 was presumably used by sway to start Steam, and Steam presumably inherited stdout from it.

It seems like both ends of a pipe have the same inode number visible in /proc, and they can only be distinguished by their permissions:

$ yes | less

# in another shell
$ ls -l /proc/$(pgrep yes)/fd/1
l-wx------ 1 smcv smcv 64 Sep 26 23:47 /proc/17157/fd/1 -> 'pipe:[118687]'
$ ls -l /proc/$(pgrep less)/fd/0
lr-x------ 1 smcv smcv 64 Sep 26 23:47 /proc/17158/fd/0 -> 'pipe:[118687]'

Since @TakuyaSama and @Technohacker are (presumably?) not using sway, I think your root cause for this symptom is probably not the same as theirs.

theaprilhare commented 3 years ago

If that's the case, then I think this would indeed be an application launcher bug - although it looks as though the application launcher might actually be sway rather than wofi/kickoff, because swaymsg exec just asks sway to start an application via IPC, rather than starting the application itself. Or, if sway is just letting applications inherit its stdout, then this could be a problem with how you start sway (whatever that is).

I was starting sway the way mentioned above -- by running a script from the console that set some environmental variables and ended with exec /usr/bin/sway -- but since apparently things run with swaymsg exec inherit sway's stdout, I decided to launch sway by changing the last line of the script from exec /usr/bin/sway to exec systemd-cat --identifier=sway sway to get stdout for sway, Steam, and everything else sent to the systemd journal.

On doing so and then launching Steam from wofi, I see a bunch of messages printed to the systemd journal of this sort:

Sep 26 20:18:45 montmorency sway[49517]: /home/raghav/.local/share/Steam/ubuntu12_64/steamwebhelper.sh: line 28: echo: write error: Broken pipe
Sep 26 20:18:55 montmorency sway[49522]: /home/raghav/.local/share/Steam/ubuntu12_64/steamwebhelper.sh: line 28: echo: write error: Broken pipe
Sep 26 20:19:05 montmorency sway[49535]: /home/raghav/.local/share/Steam/ubuntu12_64/steamwebhelper.sh: line 28: echo: write error: Broken pipe
Sep 26 20:19:06 montmorency sway[49513]: No player could handle this command

(steamwebhelper is still broken.)

Line 28 of steamwebhelper.sh is echo "Runtime for steamwebhelper: defaulting to $STEAM_RUNTIME_HEAVY".