Explore a way to listen to and capture things sent to `os_log`

[brendanlensink]

This came up in a NiceComponents PR, here

Right now, anything sent to os_log is basically lost by Steamclog, it would be nice if we're able to capture it somehow

[dayvauld]

After my investigation into this, it is possible since iOS15 to capture os_log messages within the app. (see: https://steipete.com/posts/logging-in-swift/).

There are a few caveats though, one being that basic os_log("message goes here") calls can be difficult to filter as they have no identifier, and logging/parsing the entire .default log is way too noisy to be useful. Apple/iOS outputs all sorts of logs based on screen interaction, events, and stuff like that. So everything just gets lost in the mix.
You can add a better log identifier (ie. os_log("more useful log", log: .init(subsystem: "com.app.whatever", category: "main"), type: .info) that allows for easier filtering, but it sounds like we are trying to catch os_logs from existing apps which from my investigation appear to use the basic log call.

To add to that, a quick search across all our repos reveals that we almost never use os_log so I ask how useful this addition would be, unless I'm missing some sort of context or use case.

I think the bigger discussion that is warranted is using OSLog framework in replacement of XCLogger, as discussed here: #89
(and we could get the catching of those existing os_logs for free 😄 - even if they are hard to locate)

[brendanlensink]

Yeah this seems very reasonable to me, @nbrooke do you remember why we wanted to do it this way?

[nbrooke]

do you remember why we wanted to do it this way?

I don't think there's like a specific "this way" we want to approach this, it's more just a vague sense of "it would be nice if we were integrating with the system logging to some degree", that both this bug and #89 are expressing. I think the benefits that #89 lists are still the ones that make this sort of thing desirable.

To add to that, a quick search across all our repos reveals that we almost never use os_log so I ask how useful this addition would be, unless I'm missing some sort of context or use case.

This is a bit of a chicken and egg thing. We don't use os_log a lot right now, because anything sent to it is basically useless for debugging in the field because Steamclog / Sentry doesn't capture it. Using os_log directly (and more than we are now) for all our open source libraries I think WOULD be good if Steamclog was pulling those in (because then we could get reasonable logging without needing to introduce a dependancy on Steamclog or introduce an adhoc way to pass up logs to the app, like we did in Bluejay, for example: https://github.com/steamclock/bluejay/blob/master/Bluejay/Bluejay/LogObserver.swift).

You can add a better log identifier (ie. os_log("more useful log", log: .init(subsystem: "com.app.whatever", category: "main"), type: .info) that allows for easier filtering, but it sounds like we are trying to catch os_logs from existing apps which from my investigation appear to use the basic log call.

One thing that I think IS totally reasonable to do if we go this route is to set some rules about how we need to structure the log identifiers to make them work best with Steamclog. Like we say "for Steamclock open source projects the subsystem HAS to be "com.steamclock." or Steamclog won't pick it up by default. Or you need to explicitly configure things, like somewhere in the app we need to say:

// write all Steamclog logs to this os_log subsystem
steamclogConfig.osLogExport = "com.someclient.TheirAppName.steamclog" 

// pull os_log entries from these subsystems to send to Sentry
steamclogConfig.osLogImport = [
    "com.someclient.TheirAppName.steamclog", 
    "com.steamclock.NiceComponents", 
    "com.steamclock.Switchcraft", 
    "com.someonelse.SomeLibrary"
] 

logging/parsing the entire .default log is way too noisy to be useful

The cases where we would want ALL the logs are pretty narrow, but when they happen I think it's reasonable for them to be noisy. Like one of the options we have now is to save the verbose Steamclog logs to disk and attach that file to the sentry reports of serious errors. When you hit a situation where things have gone horribly wrong, the fullest logs we can get for the last few seconds or minutes before the failure CAN be super useful even if they are very noisy. In some case there are MORE useful if they are noisy, because they might contain unintentional clues about what is happening from stuff that you didn't intentionally log from other OS subsystems or whatever.

The "full logs attached to sentry reports" scenario might be the easiest and highest value thing to start off with here. I think even just replacing the current on-disk logs with writing those to os_log (with a known subsystem) and pulling those exact same logs out when we request the recent logs, would be an improvement over what we have now, due to how twitchy things like the log rotation, disk space usage, performance, etc, are with our current slightly ad-hoc versions of those. Once we have that, extending it to also do something like the "automatically pull in all logs from 'com.steamclock.*' subsystems" and adding a subsystem to the calls in NiceComponents so we can get those logs at least when errors do happen is pretty straightforward.