52

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.

1
  • try %@ instead of %f
    – Kamran
    Commented Jun 20, 2018 at 7:15

3 Answers 3

124

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.

7
  • 16
    Dude... wow.... This is the best answer I've ever gotten on on StackOverflow, and I've been here for a while. I had a hunch I was running into a subtlety of Swift's handling of variadic arguments so thank you.
    – Mike Akers
    Commented Jun 20, 2018 at 14:04
  • For anyone trying to use _swift_os_log* functions, you'll now end up with "Use of unresolved identifier" errors.
    – zgosalvez
    Commented Jul 15, 2018 at 15:49
  • 5
    @zgosalvez Looking at the latest Swift source for os_log and you'll see that you now need to import _SwiftOSOverlayShims
    – kdubb
    Commented Oct 10, 2018 at 0:36
  • My app was crashing from this same issue with os_signpost and I couldn't figure out how to convert the [CVarArg] back to something that os_signpost() would properly interpret. Thanks for the workaround (even if it is a hack). I'll post my code for os_signpost in an answer below in case anybody wants it.
    – TimeDelta
    Commented Nov 1, 2018 at 19:57
  • 2
    Rob, you have opened the hell gate here. Cheers!
    – Stream
    Commented Apr 21, 2019 at 9:50
3

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
    }
}
0

I needed a wrapper for os_log that could log errors to crashlytics in case the type was of .error. My project is iOS 13 so I needed to to use the older os_log syntax. As Rob Mayoff mentioned there is an issue with implicit conversion from CVarArg... to Array<CVArg> causing issues when passed to the os_log method.

For me creating a simple switch on the count of the the args and doing separate calls to os_log for each count, taking out every argument from the array and passing it to os_log separately fixed the issue. The code is verbose, but it does the job for me.

func log(_ message: StaticString, log: OSLog = .default, type: OSLogType = .default, _ args: CVarArg...) {
        switch args.count {
        case 0:
            os_log(message, log: log, type: type)
        case 1:
            os_log(message, log: log, type: type, args[0])
        case 2:
            os_log(message, log: log, type: type, args[0], args[1])
        case 3:
            os_log(message, log: log, type: type, args[0], args[1], args[2])
        case 4:
            os_log(message, log: log, type: type, args[0], args[1], args[2], args[3])
        case 5:
            os_log(message, log: log, type: type, args[0], args[1], args[2], args[3], args[4])
        default:
            assertionFailure("Currently only up to five arguments are supported")
        }
        // log error to crashlytics
    }

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.