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

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.

Solution 1:

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:

Foundation (on Apple platforms) makes Array conform to the _ObjectiveCBridgeable protocol. It implements bridging of Array to Objective-C by returning an NSArray.
Foundation also makes Array conform to the CVarArg protocol.
The withVaList function asks each CVarArg to convert itself to its _cVarArgEncoding.
The default implementation of _cVarArgEncoding, for a type that conforms to both _ObjectiveCBridgeable and CVarArg, returns the bridging Objective-C object.
The conformance of Array to CVarArg means the compiler won't complain about (silently) converting an Array<CVarArg> to a CVarArg and sticking it into another Array<CVarArg>.

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.

Solution 2:

As mentioned in my comment to Rob Mayoff's answer above, for anybody experiencing the same kind of issue with os_signpost(), here is a wrapper class I made around it:

import Foundation
import os
import _SwiftOSOverlayShims

public final class Signpost {

    private final let log: OSLog

    public init(log: OSLog) {
        self.log = log
    }

    public final func begin(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil) {
        if #available(iOS 12.0, *) {
            signpost(.begin, dso: dso, name: name, idObject: idObject)
        }
    }

    public final func begin(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil, _ format: StaticString, _ arguments: CVarArg...) {
        if #available(iOS 12.0, *) {
            signpost(.begin, dso: dso, name: name, idObject: idObject, format, arguments)
        }
    }

    public final func event(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil) {
        if #available(iOS 12.0, *) {
            signpost(.event, dso: dso, name: name, idObject: idObject)
        }
    }

    public final func event(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil, _ format: StaticString, _ arguments: CVarArg...) {
        if #available(iOS 12.0, *) {
            signpost(.event, dso: dso, name: name, idObject: idObject, format, arguments)
        }
    }

    public final func end(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil) {
        if #available(iOS 12.0, *) {
            signpost(.end, dso: dso, name: name, idObject: idObject)
        }
    }

    public final func end(name: StaticString, dso: UnsafeRawPointer = #dsohandle, idObject: AnyObject? = nil, _ format: StaticString, _ arguments: CVarArg...) {
        if #available(iOS 12.0, *) {
            signpost(.end, dso: dso, name: name, idObject: idObject, format, arguments)
        }
    }

    @available(iOS 12.0, *)
    private final func signpost(_ type: OSSignpostType, dso: UnsafeRawPointer = #dsohandle, name: StaticString, idObject: AnyObject? = nil) {
        guard log.signpostsEnabled else { return }
        let signpostID = getSignpostId(forObject: idObject)
        os_signpost(type, dso: dso, log: log, name: name, signpostID: signpostID)
    }

    @available(iOS 12.0, *)
    private final func signpost(
        _ type: OSSignpostType,
        dso: UnsafeRawPointer,
        name: StaticString,
        idObject: AnyObject? = nil,
        _ format: StaticString,
        _ arguments: [CVarArg])
    {
        // This crazy mess is because [CVarArg] gets treated as a single CVarArg and repassing a CVarArg... actually passes a [CVarArg]
        // This was copied from the publicly available Swift source code at https://github.com/apple/swift/blob/master/stdlib/public/Darwin/os/os_signpost.swift#L40
        // THIS IS A HACK
        guard log.signpostsEnabled else { return }
        let signpostID = getSignpostId(forObject: idObject)
        guard signpostID != .invalid && signpostID != .null else { return }
        let ra = _swift_os_log_return_address()
        name.withUTF8Buffer { (nameBuf: UnsafeBufferPointer<UInt8>) in
            // Since dladdr is in libc, it is safe to unsafeBitCast
            // the cstring argument type.
            nameBuf.baseAddress!.withMemoryRebound(to: CChar.self, capacity: nameBuf.count) { nameStr in
                format.withUTF8Buffer { (formatBuf: UnsafeBufferPointer<UInt8>) in
                    // Since dladdr is in libc, it is safe to unsafeBitCast
                    // the cstring argument type.
                    formatBuf.baseAddress!.withMemoryRebound(to: CChar.self, capacity: formatBuf.count) { formatStr in
                        withVaList(arguments) { valist in
                            _swift_os_signpost_with_format(dso, ra, log, type, nameStr, signpostID.rawValue, formatStr, valist)
                        }
                    }
                }
            }
        }
    }

    @available(iOS 12.0, *)
    private final func getSignpostId(forObject idObject: AnyObject?) -> OSSignpostID {
        if let idObject = idObject {
            return OSSignpostID(log: log, object: idObject)
        }
        return .exclusive
    }
}

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

Solution 1:

Solution 2:

Related

Recent Posts