Why does wrapping os_log() cause doubles to not be logged correctly?

  • A+
Category:Languages

Consider the following example:

import Foundation import os.log  class OSLogWrapper {      func logDefault(_ message: StaticString, _ args: CVarArg...) {         os_log(message, type: .default, args)     }      func testWrapper() {         logDefault("WTF: %f", 1.2345)     } } 

If I create a new instance of OSLogWrapper and call testWrapper()

let logger = OSLogWrapper() logger.testWrapper() 

I get the following output in the Xcode console:

2018-06-19 18:21:08.327979-0400 WrapperWTF[50240:548958] WTF: 0.000000 

I've checked everything I can think of and I can't make heads or tails of what's going wrong here. Looking through the documentation isn't yielding anything helpful.

Thanks for the help!

 


The compiler implements variadic arguments by casting each argument to the declared variadic type, packaging them into an Array of that type, and passing that array to the variadic function. In the case of testWrapper, the declared variadic type is CVarArg, so when testWrapper calls logDefault, this is what happens under the covers: testWrapper casts 1.2345 to a CVarArg, creates an Array<CVarArg>, and passes it to logDefault as args.

Then logDefault calls os_log, passing it that Array<CVarArg> as an argument. This is the bug in your code. The bug is quite subtle. 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>. The structure looks like this:

Array<CVarArg> created in `logDefault`   |   +--> CVarArg (element at index 0)          |          +--> Array<CVarArg> (created in `testWrapper`)                 |                 +--> CVarArg (element at index 0)                        |                        +--> 1.2345 (a Double) 

Then logDefault passes this new Array<CVarArg> to os_log. So you're asking os_log to format its first element, which is (sort of) an Array<CVarArg>, using %f, which is nonsense, and you happen to get 0.000000 as output. (I say “sort of” because there are some subtleties here which I explain later.)

So, logDefault passes its incoming Array<CVarArg> as one of potentially many variadic parameters to os_log, but what you actually want logDefault to do is pass on that incoming Array<CVarArg> as the entire set of variadic parameters to os_log, without re-wrapping it. This is sometimes called “argument splatting” in other languages.

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.

The usual solution to this problem is to look for a companion function that takes the already-bundled-up variadic arguments as a single argument. Often the companion has a v added to the function name. Examples:

  • printf (variadic) and vprintf (takes a va_list, C's equivalent of Array<CVarArg>)
  • NSLog (variadic) and NSLogv (takes a va_list)
  • -[NSString initWithFormat:] (variadic) and -[NSString WithFormat:arguments:] (takes a va_list)

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.

You have two options at this point:

  • Give up on wrapping os_log in your own variadic wrapper, because there is simply no good way to do it, or

  • Take Kamran's advice (in his comment on your question) and use %@ instead of %f. But note that you can only have a single %@ (and no other format specifiers) in your message string, because you're only passing a single argument to os_log. The output looks like this:

    2018-06-20 02:22:56.132704-0500 test[39313:6086331] WTF: (     "1.2345" ) 

You could also file an enhancement request radar at https://bugreport.apple.com asking for an os_logv function, but you shouldn't expect it to be implemented any time soon.

So that's it. Do one of those two things, maybe file a radar, and move on with your life. Seriously. Stop reading here. There's nothing good after this line.


Okay, you kept reading. Let's peek under the hood of os_log. It turns out the implementation of the Swift os_log function is part of the public Swift source code:

@_exported import os @_exported import os.log import _SwiftOSOverlayShims  @available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) public func os_log(   _ type: OSLogType,   dso: UnsafeRawPointer = #dsohandle,   log: OSLog = .default,   _ message: StaticString,   _ args: CVarArg...) {   guard log.isEnabled(type: type) else { return }   let ra = _swift_os_log_return_address()    message.withUTF8Buffer { (buf: UnsafeBufferPointer<UInt8>) in     // Since dladdr is in libc, it is safe to unsafeBitCast     // the cstring argument type.     buf.baseAddress!.withMemoryRebound(       to: CChar.self, capacity: buf.count     ) { str in       withVaList(args) { valist in         _swift_os_log(dso, ra, log, type, str, valist)       }     }   } } 

So it turns out there is a version of os_log, called _swift_os_log, that takes pre-bundled arguments. The Swift wrapper uses withVaList (which is documented) to convert the Array<CVarArg> to a va_list and passes that on to _swift_os_log, which is itself also part of the public Swift source code. I won't bother quoting its code here because it's long and we don't actually need to look at it.

Anyway, even though it's not documented, we can actually call _swift_os_log. We can basically copy the source code of os_log and turn it into your logDefault function:

func logDefaultHack(_ message: StaticString, dso: UnsafeRawPointer = #dsohandle, _ args: CVarArg...) {     let ra = _swift_os_log_return_address()     message.withUTF8Buffer { (buf: UnsafeBufferPointer<UInt8>) in         buf.baseAddress!.withMemoryRebound(to: CChar.self, capacity: buf.count) { str in             withVaList(args) { valist in                 _swift_os_log(dso, ra, .default, .default, str, valist)             }         }     } } 

And it works. Test code:

func testWrapper() {     logDefault("WTF: %f", 1.2345)     logDefault("WTF: %@", 1.2345)     logDefaultHack("Hack: %f", 1.2345) } 

Output:

2018-06-20 02:22:56.131875-0500 test[39313:6086331] WTF: 0.000000 2018-06-20 02:22:56.132704-0500 test[39313:6086331] WTF: (     "1.2345" ) 2018-06-20 02:22:56.132807-0500 test[39313:6086331] Hack: 1.234500 

Would I recommend this solution? No. Hell no. The internals of os_log are an implementation detail and likely to change in future versions of Swift. So don't rely on them like this. But it's interesting to look under the covers anyway.


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. Specifically:

This silent conversion is probably often an error (as it was in your case), so it would be reasonable for the compiler to warn about it, and allow you to silence the warning with an explicit cast (e.g. args as CVarArg). You could file a bug report at https://bugs.swift.org if you want.

Comment

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen: