Tuesday, November 2, 2021

Dangerous NSLog() Calls in Swift

Daniel Jalkut (tweet):

NSLog("Failed to get modification date at URL: \(url) - \(error)")

[…]

In the scenario of my crash, the interpolation of “url” and “error” results in surprise template placeholders, because of the presence of spaces in the path that the URL represents. In my tests, a file called “Open Program Ideas File” exists and is used to test some file manipulations. When the path to this file is encoded as a URL, the name of the file becomes “Open%20Program%20Ideas%20File”. Since the error’s failure message reiterates the name of the file it couldn’t find, we end up with another copy of the percent-escaped string in the parameter to NSLog. Each instance of “%20” followed by a letter is liable to be interpreted by NSLog as a printf-style format specifier. So as far as our filename’s string is concerned, we have “%20P”, “%20I”, and “%20F” threatening to cause trouble.

[…]

If this were Objective-C, we wouldn’t run into the problem because the parameters would need to be passed as variadic arguments[…] But if we try that in Swift, we run into trouble.

Sebastian Celis:

That Swift compiler error is very unhelpful, but you should still be able to use variadic arguments — you just need to do it a bit differently. I tend to pass them all in as strings. For example:

NSLog("Oops! %@ - %@", "\(url)", "\(error)")

Norbert Heger:

As a safety measure you could add this to your project to let the compiler catch the dangerous cases[…]

BJ Homer:

I prefer this format, because I can still keep all the string interpolation “in-line”:

NSLog("%@", "Oops! \(url) - \(error)")

It’s cool—and sometimes very useful—to be able to directly interpolate Swift strings using the \() syntax. However, for logging I prefer the Python-style approach that Swift’s print() function uses:

print("Oops!", url, "-", error)

I find it more readable, and you can easily add line breaks after commas to wrap long lines or to line up pairs of arguments that go together.

Of course, print() doesn’t output to the same places as NSLog(), but you can write a wrapper function. I think that’s a good idea, anyway, as it lets you switch whether logging is enabled, log to a file if necessary, include the source location, etc. At various times, NSLog()’s output hasn’t show up at all for me or it has been duplicated. Having this more under my control has been helpful in working around such hiccups.

Here’s some code that I’ve been using to make logging more ergonomic:

func log(_ i0: @autoclosure() -> Any?,
         _ i1: @autoclosure() -> Any?,
         _ i2: @autoclosure() -> Any?,
         file: String = #file,
         line: UInt = #line,
         function: String = #function) {
    log([i0(), i1(), i2()], file: file, line: line, function: function)
}

The parameters are type Any? to avoid the compiler error about implicitly converting an Optional to Any. Unfortunately, we need a separate version for each number of parameters because @autoclosure doesn’t work with variadic parameters. These all funnel into:

func log(_ items: @autoclosure() -> [Any?],
         file: String = #file,
         line: UInt = #line,
         function: String = #function) {
    log(String(mjtPrintingOptionals: items()), file: file, line: line, function: function)
}

And to convert the array to a string:

public extension String {
    init(mjtPrinting items: [Any], separator: String = " ") {
        // @SwiftIssue: No print() that takes an Array, and no way to splat, so
        // we have to print individually.
        // https://github.com/apple/swift/blob/main/stdlib/public/core/Print.swift
        var result = ""
        var prefix = ""
        for item in items {
            result.write(prefix)
            print(item, terminator: "", to: &result)
            prefix = separator
        }
        self = result
    }

    init(mjtPrintingOptionals items: [Any?], separator: String = " ") {
        self = String(mjtPrinting: items.map { $0 ?? "nil" }, separator: separator)
    }
}

This last function unwraps the optionals before printing so that we don’t have Optional(...) cluttering the log.

2 Comments RSS · Twitter

That’s an interesting concept but what’s the use case for autoclosure here? I can see that you are directly calling these closures when creating an array so they are always executed.

@Luke It calls down to a log() function that takes a String @autoclosure, and that function only evaluates the String if logging is enabled. If logging is disabled, the parameters passed into the top-level call won’t be converted to String or even evaluated themselves. So you can do expensive stuff like a database query without impacting performance unless you’re in debug mode.

Leave a Comment