[Feature Request] Add support for logging stdout/stderr to file

[flibitijibibo]

One of Proton's more successful features is the ability to quickly generate a log file via a single environment variable, PROTON_LOG. For native games the amount of logging can vary per-application unlike Wine which has its own log filtering system, however it is reasonable to at least try to see if the game's console output provides useful information for developers to investigate. Customers have generally done an excellent job at providing Proton log files, so it makes sense to try and expand this to native games.

This would have been a tall order for the original Scout runtime, but now that we have a system where games are run inside a proper container this is at least a little bit more realistic to attempt inside something like run-in-sniper without the Steam client itself having to invade on where app output goes.

This may even have benefits for Proton as well; while the monolithic log has been useful in the general case, it may be nice for the app output to be separate from Wine's internal logging; from both a customer's and developer's point of view it's currently interleaved and it may not be immediately obvious what log lines are coming from where. The challenge in this area would be preserving the timeline that PROTON_LOG provides by having the monolithic system; this may have to be a tradeoff if it's nontrivial to track time independently for multiple logging endpoints.

[smcv]

The requested feature already exists, and can be enabled by setting environment variable STEAM_LINUX_RUNTIME_LOG=1. It has a dual effect: increasing SLR verbosity to "info" level, and redirecting stdout/stderr to SteamLinuxRuntime_whatever/var/*.log (with a symlink at slr-latest.log), for not only SLR but also the game that it wraps. If PROTON_LOG=1 is not used, then any Proton output goes to that log file as well.

However, I'm no longer convinced that this is a good long-term design: if every layer adds its own different log location, it's very easy to end up with essential information going to a file that the user doesn't know about and won't be able to attach to issue reports.

Instead, I think a better route for the future is to get all the relevant output collected in one place. In current versions of the Steam client, game output (and also SLR output, Proton output, and the Steam Client's own stdout/stderr, unless redirected) goes to ~/.steam/steam/logs/console-linux.txt and can be collected from there. Some messages (such as warnings about abnormal conditions) are logged unconditionally, while more verbose messages are only logged if requested. If Steam happens to have been run from an interactive terminal, then the same log output is duplicated to the terminal (behind the scenes, everything writes it into a pipe to srt-logger, which sends it to appropriate destinations).

For developers and advanced users, if Steam is run with SRT_LOGGER_USE_JOURNAL=1 in the environment, then log output gets collected in the systemd Journal in addition to the log file, which means its timestamps can be correlated with everything else that's going on in the system concurrently, even outside Steam's control.

I now think that as a general design principle, when there are options that increase logging verbosity, they should only increase logging verbosity, and not change the destination (log sink), which should be an orthogonal option. I've been trying to spread the meme that DEBUG_INVOCATION=1 (originating in systemd, but not particularly systemd-specific) is a good way to opt-in to more verbose logs. pressure-vessel, GLib, SDL and sdl2-compat now all respect DEBUG_INVOCATION=1, and they all treat it as a request to enable verbose-but-not-overwhelming logging, so their own log-level adjustment options only need to be used if finer-grained control is required.

I've also been trying (for several years now!) to spread the meme that diagnostic output should always go to stderr, because that avoids it corrupting machine-readable stdout (for example when a tool like steam-runtime-system-info outputs JSON), and ensures that it gets written out promptly (stderr is unbuffered, whereas stdout is fully buffered by default).

[flibitijibibo]

That all makes sense to me - will try to mess with these options soon. One thing does come to mind though...

I've also been trying (for several years now!) to spread the meme that diagnostic output should always go to stderr, because that avoids it corrupting machine-readable stdout (for example when a tool like steam-runtime-system-info outputs JSON), and ensures that it gets written out promptly (stderr is unbuffered, whereas stdout is fully buffered by default).

I wonder if this is worth documenting for SteamOS in some way, because this totally makes sense but there's never really been a clear consensus (or at least, a certifiable Correct Answer that a PC platform could enforce). SDL_Log for example doesn't follow this, but it probably should, but it also has no alternative like, say, SDL_OutputText. I think Mono is inconsistent on this too, and that's what motivated me to file a ticket... maybe Sam (SDL) or Esme (Framework Mono) have opinions about this?

[smcv]

SDL_Log for example doesn't follow [the principle that diagnostics should go to stderr], but it probably should

GLib unfortunately doesn't always either (info- and debug-level messages go to stdout by default), but it does at least have g_log_writer_default_set_use_stderr() which can be called by programs that know they aim to provide machine-readable stdout.

but it also has no alternative like, say, SDL_OutputText

Do you mean that would be an equivalent of GLib's g_print(), bypassing the logging system and writing to stdout directly?

I'm not sure how useful that really is - if you're emitting diagnostic messages then a logging framework is a good way to do it. Conversely, if you care enough about the platform-dependent differences between stdout and stderr that you know you definitely want to write to stdout, specifically (for example to emit machine-readable output), then there's limited value in a platform abstraction, and Standard C printf() (or puts() or fputs()) is right there.

[flibitijibibo]

It might depend on how accessible the various levels are - SDL on Windows for example can't access stdio and only has OutputDebugString (I think?) so its options may be limited. That said this could still be an issue on our end because SDL is our logging framework; we're using SDL_LOG_CATEGORY_APPLICATION but AFAIK even the error category routes to the same fd; I don't think we differentiate internal errors to app errors. (Again, Sam could correct me here.)

As a quick test I'll try and make a Steam branch of IMAGWZII that logs as usual via FNA/SDL3 and also intentionally crashes in a native library to get Mono to generate its own logs. It'll be ugly but will at least act as a sample of the kind of thing that we usually get by asking customers to run the game in a terminal; either way I definitely think we can do better on our end. Will update when this is live.

[smcv]

Actually SDL (at least SDL3) looks better than you think:

SDL on Windows for example can't access stdio and only has OutputDebugString (I think?)

SDL on native desktop Windows seems to try to write to stderr if it's a terminal, and also OutputDebugString. SDL on Windows/GDK (Xbox?) does only have OutputDebugString, yes. I'm not sure what would happen for a SDL game under Proton.

SDL on misc Unix (Linux, *BSD, etc., excluding Android and macOS) does use stderr, so it's already doing what I'd want it to.

trying to spread the meme that diagnostic output should always go to stderr

To be clear, this is my personal opinion rather than the Steam Runtime team's policy, although as I mentioned above, there are technical reasons why I think this.

[smcv]

diagnostic output should always go to stderr

Perhaps a better way to phrase this would have been "diagnostic output should never go to stdout". Obviously if the platform has a dedicated diagnostic channel like Windows OutputDebugString() or Android __android_log_write(), then it's fine to use that - but for historical reasons, Unix platforms don't, really.

The closest we get to a dedicated diagnostic channel on Unix is traditional syslog or the systemd Journal (which is basically super-syslog), but not everyone feels that those are appropriate for user applications (as opposed to system services) and it's a relatively recent feature for default distro installations to let unprivileged users read their own Journal messages, so stderr is the lowest-common-denominator diagnostic channel. And, in any case, there are technical reasons why things like glibc's last-gasp logging when it detects memory corruption have to go to fd 2 and can't safely go to the syslog, so we have to collect stderr somehow/somewhere anyway.

[flibitijibibo]

Sorry for the delay on this, Z0MB1ES should now have a public beta build called "pressptocrash" that should cause Mono to spew out a pretty large crash log. In general this sample has logs coming from 4 different places: Mono, SDL, FNA, and the game itself, though I don't think the game prints very much compared to all the other components.