Wednesday, March 6, 2019

Problems With os_log

BJ Homer:

Is there anyone outside Apple who finds the new logging system useful? Seems like it’s annoying and actively intrusive for external developers.

The os_log features are useful to Apple, but without anyway to gather logs for our own reporting, I don’t see how the features are useful to third party devs.

Some of the problems: difficulty getting logs from customers, so much spew that the log files are huge and hard to sift through, important log entries that are never persisted to disk, high CPU use when leaving Console open to catch the unpersisted entries, NSLog becoming unreliable and not showing anything in some cases, API that needs to be wrapped to be useful but which is designed not to be wrapped. Instead of unifying things, unified logging has resulted in everyone finding their own workarounds.

Peter Steinberger:

Ideally, we’d love to fully switch to Apple’s os_log API. However, it has one major downside: There’s still no way to access the rolling log to add to the reports that get sent back to us. Multiple radars have been submitted to Apple, requesting this feature be added (rdar://40853863, rdar://30444429), but in the meantime, developers are forced to implement their own solutions if they wish to include logging in a crash’s backtrace.

[…]

For our specific use case, we’ve decided to integrate Crashlytics’ CLSLogv function as a custom logger that we use with CocoaLumberjack, a framework that offers many other useful features, such as adding macOS logging capabilities.

Mike Piontek (tweet):

With NSLog I can have a switch in my iOS or macOS app that redirects stderr to a file. The user can turn that on, recreate the problem, and just tap a button to email the file. Super simple.

With os_log, this doesn’t work. Of course there’s sysdiagnose, but that requires a complicated button combination, scrolling through a list of hundreds of other log files, and then… basically the only option is to try to email me a 200MB file.

[…]

I was originally planning to create my own wrapper for os_log, even though it’s recommended against (see WWDC 2016). That way I could have it write to a file as needed, or just pass the data to os_log the rest of the time. But it seems there’s actually no good way to do that, due to the problems described here.

Rob Mayoff:

The problem is that os_log doesn’t take an Array<CVarArg> argument; os_log is itself variadic over CVarArg. So Swift casts args (an Array<CVarArg>) to CVarArg, and sticks that casted CVarArg into another Array<CVarArg>.

[…]

Sadly for you, Swift doesn’t yet have any syntax for argument splatting. It’s been discussed more than once in Swift-Evolution (in this thread, for example), but there’s not yet a solution on the horizon.

[…]

So you might go looking for an os_logv. Sadly, you won’t find one. There is no documented companion to os_log that takes pre-bundled arguments.

[…]

One last thing. Why doesn’t the compiler complain about converting Array<CVarArg> to CVarArg? And why does Kamran’s suggestion (of using %@) work?

It turns out these questions have the same answer: it’s because Array is “bridgeable” to an Objective-C object.

Previously:

Update (2019-03-07): Kyle Howells:

It feels like an internal tool Apple built for themselves and then asked everyone else to use for our use cases, without realising it doesn’t actually work for those uses.

See also: Custom String Interpolation and Compile-time Interpretation applied to Logging (via Tony Arnold).

Update (2019-03-08): Per Olofsson:

Add to this that os_log can’t be called from scripting languages such as python

10 Comments RSS · Twitter

"The features are useful, Console.app is better than what we used to have"

This is not from BJ Homer.

Anyway I'm always surprised to find that some developers find Console.app to be better. Better than what? Nothing? It surely looks better but I find it to be completely unusable for 2 main reasons:

- not a single piece of information I'm looking for can be found in the default log. So I end up looking for the system.log file which happens to be longer to find in the new "beautiful" UI.

- the logs are completely polluted by all the debug logs, useless logs (or stupid warnings like launchd warnings about process being inefficient) that Apple apparently doesn't care about leaving in the shipping versions of all the frameworks and tools of macOS.

@stephane Fixed; thanks.

Console is utterly useless. I honestly can't believe Apple not only designed it that way, but kept it that way.

Logging done right isn't that hard. But it seems like Apple made it hard on purpose.

Trying to explain to customers how to get useable logs is the biggest pain. That and, for me, some Apple Events problem that slows down an AppleScript's performance while Console is running.

@Doug Yeah, I’m not exactly sure what’s happening, but I also see slow AppleScript performance when using Console. Activity Monitor shows that various security processes are using much higher levels of CPU.

I found this thread while looking for a simple logger utility that would let me log events in an iOS device, also when not running under Xcode debugger.
Did not find anything suitable on the www, so I implemented my own:

https://github.com/rudifa/SwiftUtilBiP/blob/master/Shared/Util/DebugUtil.swift

If anyone wants to use it, just add DebugUtil.swift to your app and follow the instructions in the docs therein.

Please report any issues to https://github.com/rudifa/SwiftUtilBiP.

[…] possible que els lectors ja siguin familiars os_log i és, * hmm * estranyesa (tema per a un article futur, potser). Però per als no iniciats, tot el que heu de saber és això […]

So there's a whole bunch of magic going on behind the os_log calls. The functions record callsite, file/line/function off a &__dso_handle. Said dso_handle is a mach_header pointer. But passing a dso_handle down to the calls results in no displayed file/line in Xcode 15.

os_log expects that one replaces all log calls (iostream or not) with os_log_with_type() calls. This makes log forwarding from callback hooks in C++ libraries not possible, or locking a mutex to send out multiple os_logs in a call impossible since os_log's character limit is < 1K.

One can't even wrap os_log and route it within Swift. And Logger.warning() goes to error, since Apple thought it would be best to leave out a warning level even though syslog had one. Then to force everyone onto os_log, syslog was mothballed and deprecated on macOS and blocked on iOS.

So I think I figured it out why Apple's logs are so bad. os_log_impl, NSLog, and syslog instead of taking file/line/func like most reasonable loggers (f.e. __android_log_message) instead internally call __builtin_return_address(0). If the dso_handle which is just the .o file header (can get filename but not line) doesn't match up or it's an Apple library, then they can block the file/line and additional info (function).

So this means none of these logs can be isolated to a single site under a mutex and still get the correct file/line to jump to. Ideally my C++ log function could call __builtin_return_address(0) and hand that pointer down, but there's no provision for that.

Leave a Comment